[2024-05-28T07:00:17.429775Z] [info] +++ setup notes +++
[2024-05-28T07:00:17.429989Z] [info] Running on openqaworker21:20 (Linux 5.14.21-150500.55.65-default #1 SMP PREEMPT_DYNAMIC Thu May 23 04:57:11 UTC 2024 (a46829d) x86_64)
[2024-05-28T07:00:17.435182Z] [debug] Found ASSET_1, caching Tumbleweed.x86_64-1.0-libvirt-Snapshot20240527.vagrant.libvirt.box
[2024-05-28T07:00:17.458583Z] [info] Downloading Tumbleweed.x86_64-1.0-libvirt-Snapshot20240527.vagrant.libvirt.box, request #213357 sent to Cache Service
[2024-05-28T07:00:22.549613Z] [info] Download of Tumbleweed.x86_64-1.0-libvirt-Snapshot20240527.vagrant.libvirt.box processed:
[info] [#213357] Cache size of "/var/lib/openqa/cache" is 393 GiB, with limit 400 GiB
[info] [#213357] Downloading "Tumbleweed.x86_64-1.0-libvirt-Snapshot20240527.vagrant.libvirt.box" from "https://openqa.opensuse.org/tests/4226814/asset/other/Tumbleweed.x86_64-1.0-libvirt-Snapshot20240527.vagrant.libvirt.box"
[info] [#213357] Content of "/var/lib/openqa/cache/openqa.opensuse.org/Tumbleweed.x86_64-1.0-libvirt-Snapshot20240527.vagrant.libvirt.box" has not changed, updating last use

[2024-05-28T07:00:22.551708Z] [debug] Found ASSET_2, caching Tumbleweed.x86_64-1.0-virtualbox-Snapshot20240527.vagrant.virtualbox.box
[2024-05-28T07:00:22.554261Z] [info] Downloading Tumbleweed.x86_64-1.0-virtualbox-Snapshot20240527.vagrant.virtualbox.box, request #213359 sent to Cache Service
[2024-05-28T07:00:32.683330Z] [info] Download of Tumbleweed.x86_64-1.0-virtualbox-Snapshot20240527.vagrant.virtualbox.box processed:
[info] [#213359] Cache size of "/var/lib/openqa/cache" is 393 GiB, with limit 400 GiB
[info] [#213359] Downloading "Tumbleweed.x86_64-1.0-virtualbox-Snapshot20240527.vagrant.virtualbox.box" from "https://openqa.opensuse.org/tests/4226814/asset/other/Tumbleweed.x86_64-1.0-virtualbox-Snapshot20240527.vagrant.virtualbox.box"
[info] [#213359] Content of "/var/lib/openqa/cache/openqa.opensuse.org/Tumbleweed.x86_64-1.0-virtualbox-Snapshot20240527.vagrant.virtualbox.box" has not changed, updating last use

[2024-05-28T07:00:32.685594Z] [debug] Found ASSET_256, caching openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso.sha256
[2024-05-28T07:00:32.687915Z] [info] Downloading openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso.sha256, request #213360 sent to Cache Service
[2024-05-28T07:00:42.790854Z] [info] Download of openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso.sha256 processed:
[info] [#213360] Cache size of "/var/lib/openqa/cache" is 393 GiB, with limit 400 GiB
[info] [#213360] Downloading "openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso.sha256" from "https://openqa.opensuse.org/tests/4226814/asset/other/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso.sha256"
[info] [#213360] Content of "/var/lib/openqa/cache/openqa.opensuse.org/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso.sha256" has not changed, updating last use

[2024-05-28T07:00:42.793704Z] [debug] Found ISO, caching openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso
[2024-05-28T07:00:42.796694Z] [info] Downloading openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso, request #213361 sent to Cache Service
[2024-05-28T07:00:52.933387Z] [info] Download of openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso processed:
[info] [#213361] Cache size of "/var/lib/openqa/cache" is 393 GiB, with limit 400 GiB
[info] [#213361] Downloading "openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso" from "https://openqa.opensuse.org/tests/4226814/asset/iso/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso"
[info] [#213361] Content of "/var/lib/openqa/cache/openqa.opensuse.org/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso" has not changed, updating last use

[2024-05-28T07:00:52.936764Z] [info] Rsync from 'rsync://openqa.opensuse.org/tests' to '/var/lib/openqa/cache/openqa.opensuse.org', request #213362 sent to Cache Service
[2024-05-28T07:00:58.008842Z] [info] Output of rsync:
[info] [#213362] Calling: rsync -avHP --timeout 1800 rsync://openqa.opensuse.org/tests/ --delete /var/lib/openqa/cache/openqa.opensuse.org/tests/
Try 1:
receiving incremental file list

sent 1,771 bytes  received 1,161,706 bytes  775,651.33 bytes/sec
total size is 5,860,194,621  speedup is 5,036.79


[2024-05-28T07:00:58.008959Z] [info] Finished to rsync tests
[2024-05-28T07:00:58.013386Z] [debug] +++ worker notes +++
[37m[2024-05-28T07:00:58.351482Z] [debug] [pid:63630] Current version is 4.6.1716387241.58dd214 [interface v40][0m
[37m[2024-05-28T07:00:58.362175Z] [debug] [pid:63630] git hash in 'opensuse': 05d47c0cd70fd49af462c0598205d097904f46e3[0m
[37m[2024-05-28T07:00:58.377400Z] [debug] [pid:63630] git url in 'opensuse': https://github.com/os-autoinst/os-autoinst-distri-opensuse.git[0m
[37m[2024-05-28T07:00:58.706425Z] [debug] [pid:63630] usingenv DESKTOP=kde[0m
[37m[2024-05-28T07:00:58.706571Z] [debug] [pid:63630] usingenv DISTRI=opensuse[0m
[37m[2024-05-28T07:00:58.706637Z] [debug] [pid:63630] usingenv QEMUCPU=host[0m
[37m[2024-05-28T07:00:58.706699Z] [debug] [pid:63630] usingenv INSTLANG=en_US[0m
[37m[2024-05-28T07:00:58.706759Z] [debug] [pid:63630] usingenv DVD=1[0m
[37m[2024-05-28T07:00:58.706813Z] [debug] [pid:63630] usingenv KDE=1[0m
[37m[2024-05-28T07:00:58.706871Z] [debug] [pid:63630] usingenv ISO=openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso[0m
[37m[2024-05-28T07:00:58.706933Z] [debug] [pid:63630] usingenv ISO_MAXSIZE=4700372992[0m
[37m[2024-05-28T07:00:58.719432Z] [debug] [pid:63630] parse_vars (variables parsed from YAML schedule):[0m
[37m[2024-05-28T07:00:58.720174Z] [debug] [pid:63630] ---
  AUTOYAST_PREPARE_PROFILE: 1
  DESKTOP: textmode
  [0m
[37m[2024-05-28T07:00:58.720628Z] [debug] [pid:63630] ---
  - autoyast/prepare_profile
  - installation/bootloader_start
  - autoyast/installation
  - autoyast/console
  - autoyast/login
  - autoyast/verify_btrfs_quota
  - autoyast/repos
  - autoyast/clone
  - autoyast/verify_cloned_profile
  [0m
[37m[2024-05-28T07:00:58.720934Z] [debug] [pid:63630] parse_test_suite_data (data parsed from YAML test_data):[0m
[37m[2024-05-28T07:00:58.724433Z] [debug] [pid:63630] ---
  profile:
    partitioning:
      drive:
        device: /dev/vda
        enable_snapshots:
          _t: boolean
          __text: 'true'
        partitions:
          partition:
          - mount: /
            quotas:
              _t: boolean
              __text: 'true'
            subvolumes:
              _t: list
              __count: 8
              subvolume:
              - path: var
                referenced_limit: 1 GiB
              - path: usr/local
                referenced_limit: 1 GiB
              - path: tmp
                referenced_limit: 1 GiB
              - path: root
                referenced_limit: 1 GiB
              - path: srv
                referenced_limit: 1 GiB
              - path: opt
                referenced_limit: 1 GiB
  disks:
  - partitions:
    - mounting_options:
        mount_point: /
      subvolumes:
      - subvolume:
          path: var
          quota: 1.00GiB
      - subvolume:
          path: usr/local
          quota: 1.00GiB
      - subvolume:
          path: tmp
          quota: 1.00GiB
      - subvolume:
          path: root
          quota: 1.00GiB
      - subvolume:
          path: srv
          quota: 1.00GiB
      - subvolume:
          path: opt
          quota: 1.00GiB
  [0m
[37m[2024-05-28T07:00:58.729247Z] [debug] [pid:63630] scheduling prepare_profile tests/autoyast/prepare_profile.pm[0m
[37m[2024-05-28T07:00:58.747175Z] [debug] [pid:63630] scheduling bootloader_start tests/installation/bootloader_start.pm[0m
[37m[2024-05-28T07:00:58.749939Z] [debug] [pid:63630] scheduling installation tests/autoyast/installation.pm[0m
[37m[2024-05-28T07:00:58.750503Z] [debug] [pid:63630] scheduling console tests/autoyast/console.pm[0m
[37m[2024-05-28T07:00:58.751061Z] [debug] [pid:63630] scheduling login tests/autoyast/login.pm[0m
[37m[2024-05-28T07:00:58.751811Z] [debug] [pid:63630] scheduling verify_btrfs_quota tests/autoyast/verify_btrfs_quota.pm[0m
[37m[2024-05-28T07:00:58.752508Z] [debug] [pid:63630] scheduling repos tests/autoyast/repos.pm[0m
[37m[2024-05-28T07:00:58.753055Z] [debug] [pid:63630] scheduling clone tests/autoyast/clone.pm[0m
[37m[2024-05-28T07:00:58.753560Z] [debug] [pid:63630] scheduling verify_cloned_profile tests/autoyast/verify_cloned_profile.pm[0m
[2024-05-28T07:00:58.762092Z] [info] [pid:63641] cmdsrv: daemon reachable under http://*:20203/qB7uxifSCr757qLM/
[2024-05-28T07:00:58.764183Z] [info] [pid:63641] Listening at "http://[::]:20203"
Web application available at http://[::]:20203
[37m[2024-05-28T07:00:58.767362Z] [debug] [pid:63630] git hash in 'opensuse/products/opensuse/needles': 9c264ee66e0366e6bfd7b2a1d219ca52ddb44beb[0m
[37m[2024-05-28T07:00:58.785129Z] [debug] [pid:63630] git url in 'opensuse/products/opensuse/needles': git@github.com:os-autoinst/os-autoinst-needles-opensuse.git[0m
[37m[2024-05-28T07:00:58.785242Z] [debug] [pid:63630] init needles from opensuse/products/opensuse/needles[0m
[37m[2024-05-28T07:00:59.452749Z] [debug] [pid:63630] loaded 7144 needles[0m
[37m[2024-05-28T07:00:59.616148Z] [debug] [pid:63630] 63630: channel_out 16, channel_in 15[0m
[37m[2024-05-28T07:00:59.676925Z] [debug] [pid:63842] 63842: cmdpipe 14, rsppipe 17[0m
[37m[2024-05-28T07:00:59.677284Z] [debug] [pid:63842] started mgmt loop with pid 63842[0m
[37m[2024-05-28T07:00:59.737286Z] [debug] [pid:63842] Launching external video encoder: ffmpeg -y -hide_banner -nostats -r 24 -f image2pipe -vcodec ppm -i - -pix_fmt yuv420p -c:v libvpx-vp9 -crf 35 -b:v 1500k -cpu-used 1 'video.webm'[0m
[37m[2024-05-28T07:00:59.805615Z] [debug] [pid:63842] qemu version detected: 7.1.0[0m
[37m[2024-05-28T07:00:59.807369Z] [debug] [pid:63842] running `/usr/bin/chattr +C /var/lib/openqa/pool/20/raid`[0m
[37m[2024-05-28T07:00:59.820973Z] [debug] [pid:63842] Command `/usr/bin/chattr +C /var/lib/openqa/pool/20/raid` terminated with 1
  /usr/bin/chattr: Operation not supported while setting flags on /var/lib/openqa/pool/20/raid[0m
[37m[2024-05-28T07:00:59.821087Z] [debug] [pid:63842] Configuring storage controllers and block devices[0m
[37m[2024-05-28T07:00:59.821728Z] [debug] [pid:63842] running `/usr/bin/qemu-img info --output=json /var/lib/openqa/pool/20/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso`[0m
[37m[2024-05-28T07:00:59.863310Z] [debug] [pid:63842] Initializing block device images[0m
[37m[2024-05-28T07:00:59.863540Z] [debug] [pid:63842] running `/usr/bin/qemu-img create -f qcow2 /var/lib/openqa/pool/20/raid/hd0 20G`[0m
[37m[2024-05-28T07:00:59.903221Z] [debug] [pid:63842] Formatting '/var/lib/openqa/pool/20/raid/hd0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=21474836480 lazy_refcounts=off refcount_bits=16[0m
[37m[2024-05-28T07:00:59.903331Z] [debug] [pid:63842] running `/usr/bin/qemu-img create -f qcow2 -F raw -b /var/lib/openqa/pool/20/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso /var/lib/openqa/pool/20/raid/cd0-overlay0 4497342464`[0m
[37m[2024-05-28T07:00:59.942910Z] [debug] [pid:63842] Formatting '/var/lib/openqa/pool/20/raid/cd0-overlay0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=4497342464 backing_file=/var/lib/openqa/pool/20/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso backing_fmt=raw lazy_refcounts=off refcount_bits=16[0m
[37m[2024-05-28T07:00:59.943003Z] [debug] [pid:63842] init_blockdev_images: Finished creating block devices[0m
[37m[2024-05-28T07:00:59.944105Z] [debug] [pid:63842] starting: /usr/bin/qemu-system-x86_64 -device VGA,edid=on,xres=1024,yres=768 -only-migratable -chardev ringbuf,id=serial0,logfile=serial0,logappend=on -serial chardev:serial0 -audiodev none,id=snd0 -device intel-hda -device hda-output,audiodev=snd0 -global isa-fdc.fdtypeA=none -m 1536 -cpu host -netdev user,id=qanet0 -device virtio-net,netdev=qanet0,mac=52:54:00:12:34:56 -object rng-random,filename=/dev/urandom,id=rng0 -device virtio-rng-pci,rng=rng0 -boot once=d -device qemu-xhci -device usb-tablet -smp 1 -enable-kvm -no-shutdown -vnc :110,share=force-shared -device virtio-serial -chardev pipe,id=virtio_console,path=virtio_console,logfile=virtio_console.log,logappend=on -device virtconsole,chardev=virtio_console,name=org.openqa.console.virtio_console -chardev pipe,id=virtio_console_user,path=virtio_console_user,logfile=virtio_console_user.log,logappend=on -device virtconsole,chardev=virtio_console_user,name=org.openqa.console.virtio_console_user -chardev socket,path=qmp_socket,server=on,wait=off,id=qmp_socket,logfile=qmp_socket.log,logappend=on -qmp chardev:qmp_socket -S -device virtio-scsi-pci,id=scsi0 -blockdev driver=file,node-name=hd0-file,filename=/var/lib/openqa/pool/20/raid/hd0,cache.no-flush=on -blockdev driver=qcow2,node-name=hd0,file=hd0-file,cache.no-flush=on,discard=unmap -device virtio-blk,id=hd0-device,drive=hd0,serial=hd0 -blockdev driver=file,node-name=cd0-overlay0-file,filename=/var/lib/openqa/pool/20/raid/cd0-overlay0,cache.no-flush=on -blockdev driver=qcow2,node-name=cd0-overlay0,file=cd0-overlay0-file,cache.no-flush=on,discard=unmap -device scsi-cd,id=cd0-device,drive=cd0-overlay0,serial=cd0[0m
[37m[2024-05-28T07:00:59.950310Z] [debug] [pid:63842] Waiting for 0 attempts[0m
[37m[2024-05-28T07:01:00.950932Z] [debug] [pid:63842] Waiting for 1 attempts[0m
[37m[2024-05-28T07:01:01.951402Z] [debug] [pid:63842] Finished after 2 attempts[0m
[37m[2024-05-28T07:01:01.965616Z] [debug] [pid:63842] Establishing VNC connection to localhost:6010[0m
[37m[2024-05-28T07:01:01.967934Z] [debug] [pid:63842] pointer type 0 0 640 480 -257[0m
[37m[2024-05-28T07:01:01.968021Z] [debug] [pid:63842] led state 0 1 1 -261[0m
[37m[2024-05-28T07:01:02.022248Z] [debug] [pid:63842] Start CPU[0m
[37m[2024-05-28T07:01:02.022460Z] [debug] [pid:63842] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"50282","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"6010","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":966111,"seconds":1716879661}}[0m
[37m[2024-05-28T07:01:02.022548Z] [debug] [pid:63842] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"50282","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"6010","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":967117,"seconds":1716879661}}[0m
[37m[2024-05-28T07:01:02.022641Z] [debug] [pid:63842] EVENT {"event":"RESUME","timestamp":{"microseconds":22484,"seconds":1716879662}}[0m
GOT GO

[37m[2024-05-28T07:01:02.026900Z] [debug] [pid:63842] QEMU: QEMU emulator version 7.1.0 (SUSE Linux Enterprise 15)[0m
[37m[2024-05-28T07:01:02.026951Z] [debug] [pid:63842] QEMU: Copyright (c) 2003-2022 Fabrice Bellard and the QEMU Project developers[0m
[37m[2024-05-28T07:01:02.028999Z] [debug] [pid:63652] Snapshots are supported[0m
[1;34m[2024-05-28T07:01:02.030312Z] [debug] [pid:63652] ||| starting prepare_profile tests/autoyast/prepare_profile.pm[0m
[2024-05-28T07:01:02.031833Z] [debug] [pid:63652] tests/autoyast/prepare_profile.pm:22 called testapi::get_test_data
[2024-05-28T07:01:02.032117Z] [debug] [pid:63652] <<< testapi::get_test_data(path="opensuse/data/autoyast_opensuse/autoyast_btrfs_quota.xml")
[2024-05-28T07:01:02.033631Z] [debug] [pid:63652] tests/autoyast/prepare_profile.pm:27 called autoyast::prepare_ay_file -> lib/autoyast.pm:859 called testapi::get_test_data
[2024-05-28T07:01:02.033735Z] [debug] [pid:63652] <<< testapi::get_test_data(path="opensuse/data/autoyast_opensuse/autoyast_btrfs_quota.xml")
[2024-05-28T07:01:02.034181Z] [debug] [pid:63652] tests/autoyast/prepare_profile.pm:27 called autoyast::prepare_ay_file -> lib/autoyast.pm:874 called autoyast::upload_profile -> lib/autoyast.pm:742 called testapi::save_tmp_file
[2024-05-28T07:01:02.034261Z] [debug] [pid:63652] <<< testapi::save_tmp_file(path="autoyast_opensuse/autoyast_btrfs_quota.xml")
[1;34m[2024-05-28T07:01:02.036825Z] [debug] [pid:63652] ||| finished prepare_profile autoyast (runtime: 0 s)[0m
[1;34m[2024-05-28T07:01:02.099138Z] [debug] [pid:63652] ||| starting bootloader_start tests/installation/bootloader_start.pm[0m
[2024-05-28T07:01:02.099837Z] [debug] [pid:63652] tests/installation/bootloader_start.pm:83 called testapi::record_info
[2024-05-28T07:01:02.099958Z] [debug] [pid:63652] <<< testapi::record_info(title="bootloader", output="", result="ok")
[2024-05-28T07:01:02.100225Z] [debug] [pid:63652] tests/installation/bootloader_start.pm:84 called bootloader::run -> tests/installation/bootloader.pm:43 called bootloader_setup::select_bootmenu_option -> lib/bootloader_setup.pm:330 called testapi::assert_screen
[2024-05-28T07:01:02.100305Z] [debug] [pid:63652] <<< testapi::assert_screen(mustmatch="inst-bootmenu", timeout=30)
[37m[2024-05-28T07:01:03.167220Z] [debug] [pid:63842] no match: 29.0s, best candidate: bootloader-grub2-alp-selfinstall-20230327 (0.00)[0m
Input #0, image2pipe, from 'pipe:':
  Duration: N/A, bitrate: N/A
  Stream #0:0: Video: ppm, rgb24, 1024x768, 24 fps, 24 tbr, 24 tbn, 24 tbc
Stream mapping:
  Stream #0:0 -> #0:0 (ppm (native) -> vp9 (libvpx-vp9))
[libvpx-vp9 @ 0x55d84f917900] v1.11.0
Output #0, webm, to 'video.webm':
  Metadata:
    encoder         : Lavf58.76.100
  Stream #0:0: Video: vp9, yuv420p(tv, progressive), 1024x768, q=2-31, 1500 kb/s, 24 fps, 1k tbn
    Metadata:
      encoder         : Lavc58.134.100 libvpx-vp9
    Side data:
      cpb: bitrate max/min/avg: 0/0/0 buffer size: 0 vbv_delay: N/A
[37m[2024-05-28T07:01:04.086596Z] [debug] [pid:63842] no match: 28.0s, best candidate: bootloader-grub2-alp-selfinstall-20230327 (0.00)[0m
[32m[2024-05-28T07:01:05.134572Z] [debug] [pid:63652] >>> testapi::_handle_found_needle: found bootmenu-Slowroll-20240109, similarity 1.00 @ 0/0[0m
[2024-05-28T07:01:05.134803Z] [debug] [pid:63652] tests/installation/bootloader_start.pm:84 called bootloader::run -> tests/installation/bootloader.pm:43 called bootloader_setup::select_bootmenu_option -> lib/bootloader_setup.pm:348 called testapi::send_key_until_needlematch
[2024-05-28T07:01:05.134903Z] [debug] [pid:63652] <<< testapi::check_screen(mustmatch="inst-oninstallation", timeout=0)
[37m[2024-05-28T07:01:06.370974Z] [debug] [pid:63842] no match: -0.9s, best candidate: inst-oninstallation-20191209 (0.45)[0m
[32m[2024-05-28T07:01:06.440495Z] [debug] [pid:63652] >>> testapi::_check_backend_response: match=inst-oninstallation timed out after 0 (check_screen)[0m
[2024-05-28T07:01:06.455253Z] [debug] [pid:63652] tests/installation/bootloader_start.pm:84 called bootloader::run -> tests/installation/bootloader.pm:43 called bootloader_setup::select_bootmenu_option -> lib/bootloader_setup.pm:348 called testapi::send_key_until_needlematch
[2024-05-28T07:01:06.455392Z] [debug] [pid:63652] <<< testapi::wait_screen_change(timeout=10, similarity_level=50)
[2024-05-28T07:01:06.456211Z] [debug] [pid:63652] tests/installation/bootloader_start.pm:84 called bootloader::run -> tests/installation/bootloader.pm:43 called bootloader_setup::select_bootmenu_option -> lib/bootloader_setup.pm:348 called testapi::send_key_until_needlematch
[2024-05-28T07:01:06.456290Z] [debug] [pid:63652] <<< testapi::send_key(key="down", wait_screen_change=0)
[32m[2024-05-28T07:01:06.907047Z] [debug] [pid:63652] >>> testapi::wait_screen_change: screen change seen after 0.177554845809937 seconds (similarity: 25.510891502542)[0m
[2024-05-28T07:01:06.907227Z] [debug] [pid:63652] tests/installation/bootloader_start.pm:84 called bootloader::run -> tests/installation/bootloader.pm:43 called bootloader_setup::select_bootmenu_option -> lib/bootloader_setup.pm:348 called testapi::send_key_until_needlematch
[2024-05-28T07:01:06.907382Z] [debug] [pid:63652] <<< testapi::check_screen(mustmatch="inst-oninstallation", timeout=5)
[32m[2024-05-28T07:01:07.095572Z] [debug] [pid:63652] >>> testapi::_handle_found_needle: found inst-oninstallation-20191209, similarity 1.00 @ 246/192[0m
[2024-05-28T07:01:07.096075Z] [debug] [pid:63652] tests/installation/bootloader_start.pm:84 called bootloader::run -> tests/installation/bootloader.pm:53 called bootloader_setup::bootmenu_default_params -> lib/bootloader_setup.pm:623 called bootloader_setup::type_boot_parameters -> lib/bootloader_setup.pm:1592 called testapi::type_string
[2024-05-28T07:01:07.096247Z] [debug] [pid:63652] <<< testapi::type_string(string="  Y2DEBUG=1 vga=791 video=1024x768 plymouth.ignore-serial-consoles console=ttyS0 console=tty linuxrc.log=/dev/ttyS0 linuxrc.core=/dev/ttyS0 linuxrc.debug=4,trace reboot_timeout=0  ", max_interval=4, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:02:45.876487Z] [debug] [pid:63652] tests/installation/bootloader_start.pm:84 called bootloader::run -> tests/installation/bootloader.pm:56 called bootloader_setup::specific_bootmenu_params -> lib/bootloader_setup.pm:913 called bootloader_setup::type_boot_parameters -> lib/bootloader_setup.pm:1592 called testapi::type_string
[2024-05-28T07:02:45.876707Z] [debug] [pid:63652] <<< testapi::type_string(string="  ifcfg=*=dhcp SetHostname=0 autoyast=http://10.0.2.2:20203/qB7uxifSCr757qLM/files/autoyast_opensuse/autoyast_btrfs_quota.xml kernel.softlockup_panic=1  ", max_interval=4, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:04:11.344400Z] [debug] [pid:63652] tests/installation/bootloader_start.pm:84 called bootloader::run -> tests/installation/bootloader.pm:68 called testapi::send_key
[2024-05-28T07:04:11.344558Z] [debug] [pid:63652] <<< testapi::send_key(key="ret", wait_screen_change=0)
[2024-05-28T07:04:11.612569Z] [debug] [pid:63652] tests/installation/bootloader_start.pm:84 called bootloader::run -> tests/installation/bootloader.pm:71 called bootloader_setup::parse_bootparams_in_serial -> lib/bootloader_setup.pm:1507 called testapi::wait_serial
[2024-05-28T07:04:11.612792Z] [debug] [pid:63652] <<< testapi::wait_serial(expect_not_found=0, regexp=qr/command line:.*\[/msi, quiet=undef, timeout=90, record_output=undef, no_regex=0, buffer_size=undef)
[32m[2024-05-28T07:04:13.663397Z] [debug] [pid:63652] >>> testapi::wait_serial: (?^msi:command line:.*\[): ok[0m
[2024-05-28T07:04:13.663590Z] [debug] [pid:63652] tests/installation/bootloader_start.pm:84 called bootloader::run -> tests/installation/bootloader.pm:71 called bootloader_setup::compare_bootparams -> lib/bootloader_setup.pm:1530 called testapi::record_info
[2024-05-28T07:04:13.663728Z] [debug] [pid:63652] <<< testapi::record_info(title="params ok", output="Bootloader parameters are typed correctly.\nVerified parameters:\nY2DEBUG=1\nvga=791\nvideo=1024x768\nplymouth.ignore-serial-consoles\nconsole=ttyS0\nconsole=tty\nlinuxrc.log=/dev/ttyS0\nlinuxrc.core=/dev/ttyS0\nlinuxrc.debug=4,trace\nreboot_timeout=0\nifcfg=*=dhcp\nSetHostname=0\nautoyast=http://10.0.2.2:20203/qB7uxifSCr757qLM/files/autoyast_opensuse/autoyast_btrfs_quota.xml\nkernel.softlockup_panic=1", result="ok")
[1;34m[2024-05-28T07:04:13.667474Z] [debug] [pid:63652] ||| finished bootloader_start installation (runtime: 191 s)[0m
[1;34m[2024-05-28T07:04:13.668561Z] [debug] [pid:63652] ||| starting installation tests/autoyast/installation.pm[0m
[2024-05-28T07:04:13.682079Z] [debug] [pid:63652] tests/autoyast/installation.pm:109 called autoyast::test_ayp_url -> lib/autoyast.pm:800 called testapi::record_info
[2024-05-28T07:04:13.682189Z] [debug] [pid:63652] <<< testapi::record_info(title="ayp url ok", output="Autoyast profile url http://localhost:20203/qB7uxifSCr757qLM/files/autoyast_opensuse/autoyast_btrfs_quota.xml is reachable from the worker", result="ok")
[2024-05-28T07:04:13.682494Z] [debug] [pid:63652] tests/autoyast/installation.pm:169 called testapi::check_screen
[2024-05-28T07:04:13.682616Z] [debug] [pid:63652] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention"
  ], timeout=50)
[31m[2024-05-28T07:04:14.360883Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 0.68 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:04:14.360979Z] [debug] [pid:63842] no match: 49.9s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:14.684196Z] [debug] [pid:63842] no change: 48.9s[0m
[37m[2024-05-28T07:04:15.065213Z] [debug] [pid:63842] no match: 48.9s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:15.684508Z] [debug] [pid:63842] no change: 47.9s[0m
[37m[2024-05-28T07:04:16.076899Z] [debug] [pid:63842] no match: 47.9s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:16.077145Z] [debug] [pid:63842] pointer type 1 0 1024 768 -257[0m
[37m[2024-05-28T07:04:16.941472Z] [debug] [pid:63842] no match: 46.9s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:04:19.078301Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.39 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:04:19.078387Z] [debug] [pid:63842] no match: 45.9s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:19.347297Z] [debug] [pid:63842] no match: 44.5s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:20.373318Z] [debug] [pid:63842] no match: 43.5s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:21.086998Z] [debug] [pid:63842] no change: 42.5s[0m
[37m[2024-05-28T07:04:21.359084Z] [debug] [pid:63842] no match: 42.5s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:22.087447Z] [debug] [pid:63842] no change: 41.5s[0m
[37m[2024-05-28T07:04:22.343969Z] [debug] [pid:63842] no match: 41.5s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:04:24.483890Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.39 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:04:24.483982Z] [debug] [pid:63842] no match: 40.5s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:24.488614Z] [debug] [pid:63842] no change: 39.1s[0m
[37m[2024-05-28T07:04:24.743159Z] [debug] [pid:63842] no match: 39.1s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:25.745198Z] [debug] [pid:63842] no match: 38.1s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:26.490561Z] [debug] [pid:63842] no change: 37.1s[0m
[37m[2024-05-28T07:04:26.744258Z] [debug] [pid:63842] no match: 37.1s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:27.754836Z] [debug] [pid:63842] no match: 36.1s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:04:29.924158Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.43 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:04:29.924270Z] [debug] [pid:63842] no match: 35.1s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:30.240968Z] [debug] [pid:63842] no match: 33.7s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:31.239805Z] [debug] [pid:63842] no match: 32.7s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:32.241855Z] [debug] [pid:63842] no match: 31.7s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:04:34.363899Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.43 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:04:34.364011Z] [debug] [pid:63842] no match: 30.7s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:34.686575Z] [debug] [pid:63842] no match: 29.3s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:35.688103Z] [debug] [pid:63842] no match: 28.3s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:36.693665Z] [debug] [pid:63842] no match: 27.3s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:37.679452Z] [debug] [pid:63842] no match: 26.3s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:04:39.855919Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.49 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:04:39.856019Z] [debug] [pid:63842] no match: 25.3s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:40.173038Z] [debug] [pid:63842] no match: 23.8s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:41.181828Z] [debug] [pid:63842] no match: 22.8s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:42.186464Z] [debug] [pid:63842] no match: 21.8s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:04:44.395975Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.53 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:04:44.396085Z] [debug] [pid:63842] no match: 20.8s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:44.706176Z] [debug] [pid:63842] no match: 19.2s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:45.715605Z] [debug] [pid:63842] no match: 18.2s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:46.727699Z] [debug] [pid:63842] no match: 17.2s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:47.724185Z] [debug] [pid:63842] no match: 16.2s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:04:49.846532Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.45 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:04:49.846624Z] [debug] [pid:63842] no match: 15.2s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:50.166800Z] [debug] [pid:63842] no match: 13.8s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:51.168477Z] [debug] [pid:63842] no match: 12.8s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:52.167005Z] [debug] [pid:63842] no match: 11.8s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:04:54.303164Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.45 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:04:54.303270Z] [debug] [pid:63842] no match: 10.8s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:54.610703Z] [debug] [pid:63842] no match: 9.3s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:55.614833Z] [debug] [pid:63842] no match: 8.3s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:56.613489Z] [debug] [pid:63842] no match: 7.3s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:04:57.661392Z] [debug] [pid:63842] no match: 6.3s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:04:59.714331Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.40 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:04:59.714419Z] [debug] [pid:63842] no match: 5.3s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:00.034478Z] [debug] [pid:63842] no match: 3.9s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:01.085807Z] [debug] [pid:63842] no match: 2.9s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:01.720144Z] [debug] [pid:63842] no change: 1.9s[0m
[37m[2024-05-28T07:05:02.092245Z] [debug] [pid:63842] no match: 1.9s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:05:04.195556Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.47 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:04.195645Z] [debug] [pid:63842] no match: 0.9s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:05:05.700107Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.50 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:05.700223Z] [debug] [pid:63842] no match: -0.6s, best candidate: grub2-TW-20220603 (0.00)[0m
[32m[2024-05-28T07:05:05.981048Z] [debug] [pid:63652] >>> testapi::_check_backend_response: match=autoyast-boot,autoyast-error,bios-boot,import-untrusted-gpg-key,linuxrc-install-fail,manual-intervention,nonexisting-package,nvidia-validation-failed,package-notification,reboot-after-installation,scc-invalid-url,warning-pop-up timed out after 50 (check_screen)[0m
[2024-05-28T07:05:05.996046Z] [debug] [pid:63652] tests/autoyast/installation.pm:179 called installation::verify_timeout_and_check_screen -> tests/autoyast/installation.pm:103 called testapi::check_screen
[2024-05-28T07:05:05.996192Z] [debug] [pid:63652] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention"
  ], timeout=50)
[37m[2024-05-28T07:05:06.376999Z] [debug] [pid:63842] no match: 49.9s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:06.999809Z] [debug] [pid:63842] no change: 48.9s[0m
[37m[2024-05-28T07:05:07.266398Z] [debug] [pid:63842] no match: 48.9s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:08.263635Z] [debug] [pid:63842] no match: 47.9s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:09.265393Z] [debug] [pid:63842] no match: 46.9s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:05:11.433219Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.43 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:11.433301Z] [debug] [pid:63842] no match: 45.9s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:11.696605Z] [debug] [pid:63842] no match: 44.5s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:12.698195Z] [debug] [pid:63842] no match: 43.5s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:13.726080Z] [debug] [pid:63842] no match: 42.5s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:14.702295Z] [debug] [pid:63842] no match: 41.5s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:05:16.878959Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.44 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:16.879051Z] [debug] [pid:63842] no match: 40.5s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:16.882382Z] [debug] [pid:63842] no change: 39.1s[0m
[37m[2024-05-28T07:05:17.140614Z] [debug] [pid:63842] no match: 39.1s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:18.151494Z] [debug] [pid:63842] no match: 38.1s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:19.152280Z] [debug] [pid:63842] no match: 37.1s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:19.885103Z] [debug] [pid:63842] no change: 36.1s[0m
[37m[2024-05-28T07:05:20.142969Z] [debug] [pid:63842] no match: 36.1s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:05:22.284833Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.40 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:22.284918Z] [debug] [pid:63842] no match: 35.1s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:22.549109Z] [debug] [pid:63842] no match: 33.7s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:23.557440Z] [debug] [pid:63842] no match: 32.7s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:24.563907Z] [debug] [pid:63842] no match: 31.7s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:05:26.741198Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.45 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:26.741280Z] [debug] [pid:63842] no match: 30.7s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:26.744447Z] [debug] [pid:63842] no change: 29.2s[0m
[37m[2024-05-28T07:05:27.000744Z] [debug] [pid:63842] no match: 29.2s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:28.032781Z] [debug] [pid:63842] no match: 28.2s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:29.011749Z] [debug] [pid:63842] no match: 27.2s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:30.013271Z] [debug] [pid:63842] no match: 26.2s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:05:32.159494Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.41 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:32.159602Z] [debug] [pid:63842] no match: 25.2s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:32.163115Z] [debug] [pid:63842] no change: 23.8s[0m
[37m[2024-05-28T07:05:32.421112Z] [debug] [pid:63842] no match: 23.8s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:33.426215Z] [debug] [pid:63842] no match: 22.8s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:34.426494Z] [debug] [pid:63842] no match: 21.8s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:05:36.556753Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.39 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:36.556853Z] [debug] [pid:63842] no match: 20.8s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:36.560244Z] [debug] [pid:63842] no change: 19.4s[0m
[37m[2024-05-28T07:05:36.815425Z] [debug] [pid:63842] no match: 19.4s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:37.832864Z] [debug] [pid:63842] no match: 18.4s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:38.821834Z] [debug] [pid:63842] no match: 17.4s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:39.562540Z] [debug] [pid:63842] no change: 16.4s[0m
[37m[2024-05-28T07:05:39.823430Z] [debug] [pid:63842] no match: 16.4s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:05:41.968138Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.40 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:41.968238Z] [debug] [pid:63842] no match: 15.4s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:41.971614Z] [debug] [pid:63842] no change: 14.0s[0m
[37m[2024-05-28T07:05:42.227676Z] [debug] [pid:63842] no match: 14.0s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:43.233720Z] [debug] [pid:63842] no match: 13.0s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:44.239698Z] [debug] [pid:63842] no match: 12.0s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:45.240336Z] [debug] [pid:63842] no match: 11.0s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:05:47.371552Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.39 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:47.371652Z] [debug] [pid:63842] no match: 10.0s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:47.374837Z] [debug] [pid:63842] no change: 8.6s[0m
[37m[2024-05-28T07:05:47.630132Z] [debug] [pid:63842] no match: 8.6s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:48.634946Z] [debug] [pid:63842] no match: 7.6s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:49.645070Z] [debug] [pid:63842] no match: 6.6s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:05:51.768368Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.39 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:51.768454Z] [debug] [pid:63842] no match: 5.6s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:51.771801Z] [debug] [pid:63842] no change: 4.2s[0m
[37m[2024-05-28T07:05:52.026230Z] [debug] [pid:63842] no match: 4.2s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:53.031190Z] [debug] [pid:63842] no match: 3.2s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:54.043966Z] [debug] [pid:63842] no match: 2.2s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:54.774279Z] [debug] [pid:63842] no change: 1.2s[0m
[37m[2024-05-28T07:05:55.033753Z] [debug] [pid:63842] no match: 1.2s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:05:57.176197Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.40 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:57.176301Z] [debug] [pid:63842] no match: 0.2s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:05:58.580238Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.40 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:58.580328Z] [debug] [pid:63842] no match: -1.2s, best candidate: grub2-TW-20220603 (0.00)[0m
[32m[2024-05-28T07:05:58.792074Z] [debug] [pid:63652] >>> testapi::_check_backend_response: match=autoyast-boot,autoyast-error,bios-boot,import-untrusted-gpg-key,linuxrc-install-fail,manual-intervention,nonexisting-package,nvidia-validation-failed,package-notification,reboot-after-installation,scc-invalid-url,warning-pop-up timed out after 50 (check_screen)[0m
[2024-05-28T07:05:58.806253Z] [debug] [pid:63652] tests/autoyast/installation.pm:179 called installation::verify_timeout_and_check_screen -> tests/autoyast/installation.pm:103 called testapi::check_screen
[2024-05-28T07:05:58.806434Z] [debug] [pid:63652] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention"
  ], timeout=50)
[37m[2024-05-28T07:05:59.178527Z] [debug] [pid:63842] no match: 49.9s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:05:59.808386Z] [debug] [pid:63842] no change: 48.9s[0m
[37m[2024-05-28T07:06:00.074701Z] [debug] [pid:63842] no match: 48.9s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:00.809245Z] [debug] [pid:63842] no change: 47.9s[0m
[37m[2024-05-28T07:06:01.068779Z] [debug] [pid:63842] no match: 47.9s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:01.809829Z] [debug] [pid:63842] no change: 46.9s[0m
[37m[2024-05-28T07:06:02.066246Z] [debug] [pid:63842] no match: 46.9s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:06:04.199611Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.39 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:06:04.199703Z] [debug] [pid:63842] no match: 45.9s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:04.202019Z] [debug] [pid:63842] no change: 44.6s[0m
[37m[2024-05-28T07:06:04.464678Z] [debug] [pid:63842] no match: 44.6s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:05.203110Z] [debug] [pid:63842] no change: 43.6s[0m
[37m[2024-05-28T07:06:05.465265Z] [debug] [pid:63842] no match: 43.6s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:06.466744Z] [debug] [pid:63842] no match: 42.6s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:07.464821Z] [debug] [pid:63842] no match: 41.6s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:06:09.579385Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.37 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:06:09.579488Z] [debug] [pid:63842] no match: 40.6s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:09.582694Z] [debug] [pid:63842] no change: 39.2s[0m
[37m[2024-05-28T07:06:09.838772Z] [debug] [pid:63842] no match: 39.2s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:10.583948Z] [debug] [pid:63842] no change: 38.2s[0m
[37m[2024-05-28T07:06:10.853723Z] [debug] [pid:63842] no match: 38.2s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:11.584773Z] [debug] [pid:63842] no change: 37.2s[0m
[37m[2024-05-28T07:06:11.846312Z] [debug] [pid:63842] no match: 37.2s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:12.847370Z] [debug] [pid:63842] no match: 36.2s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:06:14.967782Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.38 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:06:14.967866Z] [debug] [pid:63842] no match: 35.2s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:14.971284Z] [debug] [pid:63842] no change: 33.8s[0m
[37m[2024-05-28T07:06:15.226366Z] [debug] [pid:63842] no match: 33.8s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:16.235465Z] [debug] [pid:63842] no match: 32.8s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:16.972917Z] [debug] [pid:63842] no change: 31.8s[0m
[37m[2024-05-28T07:06:17.233976Z] [debug] [pid:63842] no match: 31.8s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:06:19.370951Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.40 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:06:19.371041Z] [debug] [pid:63842] no match: 30.8s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:19.374410Z] [debug] [pid:63842] no change: 29.4s[0m
[37m[2024-05-28T07:06:19.630744Z] [debug] [pid:63842] no match: 29.4s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:20.643316Z] [debug] [pid:63842] no match: 28.4s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:21.638578Z] [debug] [pid:63842] no match: 27.4s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:22.378287Z] [debug] [pid:63842] no change: 26.4s[0m
[37m[2024-05-28T07:06:22.637591Z] [debug] [pid:63842] no match: 26.4s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:06:24.765432Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.39 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:06:24.765525Z] [debug] [pid:63842] no match: 25.4s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:25.032781Z] [debug] [pid:63842] no match: 24.0s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:26.030027Z] [debug] [pid:63842] no match: 23.0s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:26.770304Z] [debug] [pid:63842] no change: 22.0s[0m
[37m[2024-05-28T07:06:27.027243Z] [debug] [pid:63842] no match: 22.0s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:28.032660Z] [debug] [pid:63842] no match: 21.0s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:06:30.155320Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.38 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:06:30.155403Z] [debug] [pid:63842] no match: 20.0s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:30.423339Z] [debug] [pid:63842] no match: 18.6s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:31.159670Z] [debug] [pid:63842] no change: 17.6s[0m
[37m[2024-05-28T07:06:31.422773Z] [debug] [pid:63842] no match: 17.6s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:32.160582Z] [debug] [pid:63842] no change: 16.6s[0m
[37m[2024-05-28T07:06:32.432297Z] [debug] [pid:63842] no match: 16.6s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:06:34.538195Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.38 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:06:34.538282Z] [debug] [pid:63842] no match: 15.6s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:34.541316Z] [debug] [pid:63842] no change: 14.2s[0m
[37m[2024-05-28T07:06:34.800983Z] [debug] [pid:63842] no match: 14.2s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:35.542262Z] [debug] [pid:63842] no change: 13.2s[0m
[37m[2024-05-28T07:06:35.805917Z] [debug] [pid:63842] no match: 13.2s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:36.542960Z] [debug] [pid:63842] no change: 12.2s[0m
[37m[2024-05-28T07:06:36.801929Z] [debug] [pid:63842] no match: 12.2s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:37.543568Z] [debug] [pid:63842] no change: 11.2s[0m
[37m[2024-05-28T07:06:37.803422Z] [debug] [pid:63842] no match: 11.2s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:06:39.925829Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.38 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:06:39.925928Z] [debug] [pid:63842] no match: 10.2s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:39.928986Z] [debug] [pid:63842] no change: 8.8s[0m
[37m[2024-05-28T07:06:40.186546Z] [debug] [pid:63842] no match: 8.8s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:40.929854Z] [debug] [pid:63842] no change: 7.8s[0m
[37m[2024-05-28T07:06:41.208329Z] [debug] [pid:63842] no match: 7.8s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:41.931085Z] [debug] [pid:63842] no change: 6.8s[0m
[37m[2024-05-28T07:06:42.194804Z] [debug] [pid:63842] no match: 6.8s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:06:44.329008Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.40 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:06:44.329087Z] [debug] [pid:63842] no match: 5.8s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:44.332053Z] [debug] [pid:63842] no change: 4.4s[0m
[37m[2024-05-28T07:06:44.635063Z] [debug] [pid:63842] no match: 4.4s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:45.336081Z] [debug] [pid:63842] no change: 3.4s[0m
[37m[2024-05-28T07:06:45.591243Z] [debug] [pid:63842] no match: 3.4s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:46.334099Z] [debug] [pid:63842] no change: 2.4s[0m
[37m[2024-05-28T07:06:46.615256Z] [debug] [pid:63842] no match: 2.4s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:47.332570Z] [debug] [pid:63842] no change: 1.4s[0m
[37m[2024-05-28T07:06:47.603306Z] [debug] [pid:63842] no match: 1.4s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:06:49.713709Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.38 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:06:49.713804Z] [debug] [pid:63842] no match: 0.4s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:06:51.108594Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.39 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:06:51.108690Z] [debug] [pid:63842] no match: -1.0s, best candidate: grub2-TW-20220603 (0.00)[0m
[32m[2024-05-28T07:06:51.198573Z] [debug] [pid:63652] >>> testapi::_check_backend_response: match=autoyast-boot,autoyast-error,bios-boot,import-untrusted-gpg-key,linuxrc-install-fail,manual-intervention,nonexisting-package,nvidia-validation-failed,package-notification,reboot-after-installation,scc-invalid-url,warning-pop-up timed out after 50 (check_screen)[0m
[2024-05-28T07:06:51.212099Z] [debug] [pid:63652] tests/autoyast/installation.pm:179 called installation::verify_timeout_and_check_screen -> tests/autoyast/installation.pm:103 called testapi::check_screen
[2024-05-28T07:06:51.212239Z] [debug] [pid:63652] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention"
  ], timeout=50)
[37m[2024-05-28T07:06:51.591909Z] [debug] [pid:63842] no match: 49.9s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:52.478753Z] [debug] [pid:63842] no match: 48.9s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:53.214882Z] [debug] [pid:63842] no change: 47.9s[0m
[37m[2024-05-28T07:06:53.483114Z] [debug] [pid:63842] no match: 47.9s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:54.215711Z] [debug] [pid:63842] no change: 46.9s[0m
[37m[2024-05-28T07:06:54.479777Z] [debug] [pid:63842] no match: 46.9s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:06:56.644594Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.43 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:06:56.644710Z] [debug] [pid:63842] no match: 45.9s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:56.647018Z] [debug] [pid:63842] no change: 44.5s[0m
[37m[2024-05-28T07:06:56.903031Z] [debug] [pid:63842] no match: 44.5s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:57.648437Z] [debug] [pid:63842] no change: 43.5s[0m
[37m[2024-05-28T07:06:57.909426Z] [debug] [pid:63842] no match: 43.5s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:58.648907Z] [debug] [pid:63842] no change: 42.5s[0m
[37m[2024-05-28T07:06:58.948258Z] [debug] [pid:63842] no match: 42.5s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:06:59.917661Z] [debug] [pid:63842] no match: 41.5s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:07:02.075773Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.42 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:07:02.075857Z] [debug] [pid:63842] no match: 40.5s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:02.079345Z] [debug] [pid:63842] no change: 39.1s[0m
[37m[2024-05-28T07:07:02.336868Z] [debug] [pid:63842] no match: 39.1s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:03.348041Z] [debug] [pid:63842] no match: 38.1s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:04.082138Z] [debug] [pid:63842] no change: 37.1s[0m
[37m[2024-05-28T07:07:04.339913Z] [debug] [pid:63842] no match: 37.1s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:05.081839Z] [debug] [pid:63842] no change: 36.1s[0m
[37m[2024-05-28T07:07:05.354460Z] [debug] [pid:63842] no match: 36.1s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:07:07.606353Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.52 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:07:07.606440Z] [debug] [pid:63842] no match: 35.1s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:07.870480Z] [debug] [pid:63842] no match: 33.6s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:08.868816Z] [debug] [pid:63842] no match: 32.6s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:09.609276Z] [debug] [pid:63842] no change: 31.6s[0m
[37m[2024-05-28T07:07:09.868117Z] [debug] [pid:63842] no match: 31.6s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:07:12.021991Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.41 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:07:12.022085Z] [debug] [pid:63842] no match: 30.6s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:12.025253Z] [debug] [pid:63842] no change: 29.1s[0m
[37m[2024-05-28T07:07:12.286756Z] [debug] [pid:63842] no match: 29.1s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:13.026489Z] [debug] [pid:63842] no change: 28.1s[0m
[37m[2024-05-28T07:07:13.286357Z] [debug] [pid:63842] no match: 28.1s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:14.028476Z] [debug] [pid:63842] no change: 27.1s[0m
[37m[2024-05-28T07:07:14.288922Z] [debug] [pid:63842] no match: 27.1s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:15.029503Z] [debug] [pid:63842] no change: 26.1s[0m
[37m[2024-05-28T07:07:15.291138Z] [debug] [pid:63842] no match: 26.1s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:07:17.455026Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.42 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:07:17.455107Z] [debug] [pid:63842] no match: 25.1s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:17.458217Z] [debug] [pid:63842] no change: 23.7s[0m
[37m[2024-05-28T07:07:17.720483Z] [debug] [pid:63842] no match: 23.7s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:18.459201Z] [debug] [pid:63842] no change: 22.7s[0m
[37m[2024-05-28T07:07:18.722006Z] [debug] [pid:63842] no match: 22.7s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:19.459730Z] [debug] [pid:63842] no change: 21.7s[0m
[37m[2024-05-28T07:07:19.719788Z] [debug] [pid:63842] no match: 21.7s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:07:21.885149Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.42 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:07:21.885232Z] [debug] [pid:63842] no match: 20.7s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:21.888289Z] [debug] [pid:63842] no change: 19.3s[0m
[37m[2024-05-28T07:07:22.146118Z] [debug] [pid:63842] no match: 19.3s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:22.887716Z] [debug] [pid:63842] no change: 18.3s[0m
[37m[2024-05-28T07:07:23.146575Z] [debug] [pid:63842] no match: 18.3s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:24.152052Z] [debug] [pid:63842] no match: 17.3s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:25.149787Z] [debug] [pid:63842] no match: 16.3s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:07:27.307137Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.42 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:07:27.307222Z] [debug] [pid:63842] no match: 15.3s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:27.575774Z] [debug] [pid:63842] no match: 13.9s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:28.629732Z] [debug] [pid:63842] no match: 12.9s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:29.724748Z] [debug] [pid:63842] no match: 11.8s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:07:32.551773Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.24 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:07:32.551857Z] [debug] [pid:63842] no match: 10.9s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:32.887826Z] [debug] [pid:63842] no match: 8.6s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:33.939740Z] [debug] [pid:63842] no match: 7.6s, best candidate: grub2-TW-20220603 (0.00)[0m
[32m[2024-05-28T07:07:34.862423Z] [debug] [pid:63652] >>> testapi::_handle_found_needle: found grub2-TW-virtio-20190303, similarity 1.00 @ 11/147[0m
[2024-05-28T07:07:34.862670Z] [debug] [pid:63652] tests/autoyast/installation.pm:181 called testapi::send_key
[2024-05-28T07:07:34.862773Z] [debug] [pid:63652] <<< testapi::send_key(key="ret", wait_screen_change=0)
[2024-05-28T07:07:35.130606Z] [debug] [pid:63652] tests/autoyast/installation.pm:345 called testapi::check_screen
[2024-05-28T07:07:35.130795Z] [debug] [pid:63652] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention"
  ], timeout=50)
[37m[2024-05-28T07:07:35.935801Z] [debug] [pid:63842] no match: 49.5s, best candidate: grub2-tumbleweed-20220711 (0.29)[0m
[37m[2024-05-28T07:07:36.827775Z] [debug] [pid:63842] no match: 48.5s, best candidate: grub2-tumbleweed-20220711 (0.29)[0m
[37m[2024-05-28T07:07:37.938993Z] [debug] [pid:63842] no match: 47.5s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:38.925603Z] [debug] [pid:63842] no match: 46.5s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:07:41.018356Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.46 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:07:41.018440Z] [debug] [pid:63842] no match: 45.5s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:41.404837Z] [debug] [pid:63842] no match: 44.1s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:42.390850Z] [debug] [pid:63842] no match: 43.1s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:43.389706Z] [debug] [pid:63842] no match: 42.1s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:44.388777Z] [debug] [pid:63842] no match: 41.1s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:07:46.450276Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.43 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:07:46.450357Z] [debug] [pid:63842] no match: 40.1s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:46.753966Z] [debug] [pid:63842] no match: 38.6s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:47.754284Z] [debug] [pid:63842] no match: 37.6s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:48.754560Z] [debug] [pid:63842] no match: 36.6s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:07:50.861738Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.40 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:07:50.861833Z] [debug] [pid:63842] no match: 35.6s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:51.133133Z] [debug] [pid:63842] no match: 34.2s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:52.155053Z] [debug] [pid:63842] no match: 33.2s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:52.867010Z] [debug] [pid:63842] no change: 32.2s[0m
[37m[2024-05-28T07:07:53.155255Z] [debug] [pid:63842] no match: 32.2s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:53.867707Z] [debug] [pid:63842] no change: 31.2s[0m
[37m[2024-05-28T07:07:54.156884Z] [debug] [pid:63842] no match: 31.2s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:07:56.267633Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.40 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:07:56.267715Z] [debug] [pid:63842] no match: 30.2s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:56.270745Z] [debug] [pid:63842] no change: 28.8s[0m
[37m[2024-05-28T07:07:56.553064Z] [debug] [pid:63842] no match: 28.8s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:57.273426Z] [debug] [pid:63842] no change: 27.8s[0m
[37m[2024-05-28T07:07:57.567232Z] [debug] [pid:63842] no match: 27.8s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:07:58.273838Z] [debug] [pid:63842] no change: 26.8s[0m
[37m[2024-05-28T07:07:58.560550Z] [debug] [pid:63842] no match: 26.8s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:08:00.681157Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.41 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:08:00.681238Z] [debug] [pid:63842] no match: 25.8s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:08:00.684306Z] [debug] [pid:63842] no change: 24.4s[0m
[37m[2024-05-28T07:08:00.988385Z] [debug] [pid:63842] no match: 24.4s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:08:01.974097Z] [debug] [pid:63842] no match: 23.4s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:08:02.688283Z] [debug] [pid:63842] no change: 22.4s[0m
[37m[2024-05-28T07:08:02.976735Z] [debug] [pid:63842] no match: 22.4s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:08:03.685482Z] [debug] [pid:63842] no change: 21.4s[0m
[37m[2024-05-28T07:08:03.973586Z] [debug] [pid:63842] no match: 21.4s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:08:06.100947Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.41 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:08:06.101033Z] [debug] [pid:63842] no match: 20.4s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:08:06.391903Z] [debug] [pid:63842] no match: 19.0s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:08:07.103520Z] [debug] [pid:63842] no change: 18.0s[0m
[37m[2024-05-28T07:08:07.385541Z] [debug] [pid:63842] no match: 18.0s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:08:08.104480Z] [debug] [pid:63842] no change: 17.0s[0m
[37m[2024-05-28T07:08:08.390978Z] [debug] [pid:63842] no match: 17.0s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:08:09.105264Z] [debug] [pid:63842] no change: 16.0s[0m
[37m[2024-05-28T07:08:09.390925Z] [debug] [pid:63842] no match: 16.0s, best candidate: grub2-TW-20220603 (0.00)[0m
[31m[2024-05-28T07:08:11.500989Z] [warn] [pid:63842] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.39 seconds for 54 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:08:11.501067Z] [debug] [pid:63842] no match: 15.0s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:08:11.778170Z] [debug] [pid:63842] no match: 13.6s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:08:12.780494Z] [debug] [pid:63842] no match: 12.6s, best candidate: grub2-TW-20220603 (0.00)[0m
[37m[2024-05-28T07:08:13.802485Z] [debug] [pid:63842] no match: 11.6s, best candidate: grub2-TW-20220603 (0.00)[0m
[32m[2024-05-28T07:08:15.939531Z] [debug] [pid:63652] >>> testapi::_handle_found_needle: found linux-login-autoyast-20191126, similarity 0.99 @ 62/319[0m
[1;34m[2024-05-28T07:08:15.981973Z] [debug] [pid:63652] ||| finished installation autoyast (runtime: 242 s)[0m
[1;34m[2024-05-28T07:08:15.983897Z] [debug] [pid:63652] ||| starting console tests/autoyast/console.pm[0m
[2024-05-28T07:08:15.984457Z] [debug] [pid:63652] tests/autoyast/console.pm:22 called testapi::select_console
[2024-05-28T07:08:15.984562Z] [debug] [pid:63652] <<< testapi::select_console(testapi_console="root-console")
[37m[2024-05-28T07:08:16.393152Z] [debug] [pid:63652] activate_console, console: root-console, type: console[0m
[2024-05-28T07:08:16.393544Z] [debug] [pid:63652] tests/autoyast/console.pm:22 called testapi::select_console -> lib/susedistribution.pm:857 called testapi::wait_still_screen
[2024-05-28T07:08:16.393791Z] [debug] [pid:63652] <<< testapi::wait_still_screen(stilltime=1, similarity_level=47, timeout=30)
[32m[2024-05-28T07:08:17.921141Z] [debug] [pid:63652] >>> testapi::wait_still_screen: detected same image for 1 seconds (1.52097797393799 s elapsed), last detected similarity is 50.4372371212676[0m
[2024-05-28T07:08:17.921333Z] [debug] [pid:63652] tests/autoyast/console.pm:22 called testapi::select_console -> lib/susedistribution.pm:862 called testapi::assert_screen
[2024-05-28T07:08:17.921502Z] [debug] [pid:63652] <<< testapi::assert_screen(mustmatch=[
    "tty6-selected",
    "text-logged-in-root"
  ], timeout=60)
[32m[2024-05-28T07:08:18.029284Z] [debug] [pid:63652] >>> testapi::_handle_found_needle: found login-prompt-centos-20210810, similarity 1.00 @ 63/98[0m
[2024-05-28T07:08:18.029912Z] [debug] [pid:63652] tests/autoyast/console.pm:22 called testapi::select_console -> lib/susedistribution.pm:864 called testapi::enter_cmd
[2024-05-28T07:08:18.030051Z] [debug] [pid:63652] <<< testapi::type_string(string="root\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:08:18.199092Z] [debug] [pid:63652] tests/autoyast/console.pm:22 called testapi::select_console -> lib/susedistribution.pm:865 called susedistribution::handle_password_prompt -> lib/susedistribution.pm:70 called testapi::assert_screen
[2024-05-28T07:08:18.199257Z] [debug] [pid:63652] <<< testapi::assert_screen(mustmatch="password-prompt", timeout=60)
[32m[2024-05-28T07:08:19.053648Z] [debug] [pid:63652] >>> testapi::_handle_found_needle: found password-prompt-20160812, similarity 1.00 @ 0/112[0m
[2024-05-28T07:08:19.053836Z] [debug] [pid:63652] tests/autoyast/console.pm:22 called testapi::select_console -> lib/susedistribution.pm:865 called susedistribution::handle_password_prompt -> lib/susedistribution.pm:79 called testapi::type_password
[2024-05-28T07:08:19.054005Z] [debug] [pid:63652] <<< testapi::type_string(string="[masked]", max_interval=100, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:08:20.259956Z] [debug] [pid:63652] tests/autoyast/console.pm:22 called testapi::select_console -> lib/susedistribution.pm:865 called susedistribution::handle_password_prompt -> lib/susedistribution.pm:81 called testapi::send_key
[2024-05-28T07:08:20.260219Z] [debug] [pid:63652] <<< testapi::send_key(key="ret", wait_screen_change=0)
[2024-05-28T07:08:20.528241Z] [debug] [pid:63652] tests/autoyast/console.pm:22 called testapi::select_console -> lib/susedistribution.pm:876 called testapi::assert_screen
[2024-05-28T07:08:20.528551Z] [debug] [pid:63652] <<< testapi::assert_screen(mustmatch="text-logged-in-root", timeout=60)
[37m[2024-05-28T07:08:20.539498Z] [debug] [pid:63842] no match: 59.9s, best candidate: text-logged-in-root-20170627 (0.78)[0m
[32m[2024-05-28T07:08:21.589464Z] [debug] [pid:63652] >>> testapi::_handle_found_needle: found text-logged-in-root-20151204, similarity 1.00 @ 55/144[0m
[2024-05-28T07:08:21.589635Z] [debug] [pid:63652] tests/autoyast/console.pm:22 called testapi::select_console -> lib/susedistribution.pm:879 called testapi::assert_screen
[2024-05-28T07:08:21.589735Z] [debug] [pid:63652] <<< testapi::assert_screen(mustmatch="root-console", timeout=30)
[32m[2024-05-28T07:08:22.603338Z] [debug] [pid:63652] >>> testapi::_handle_found_needle: found root-console-20180724, similarity 1.00 @ 80/144[0m
[2024-05-28T07:08:22.603621Z] [debug] [pid:63652] tests/autoyast/console.pm:22 called testapi::select_console -> lib/susedistribution.pm:933 called distribution::script_run
[2024-05-28T07:08:22.603788Z] [debug] [pid:63652] <<< testapi::type_string(string="setterm -blank 0", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:08:23.145075Z] [debug] [pid:63652] tests/autoyast/console.pm:22 called testapi::select_console -> lib/susedistribution.pm:933 called distribution::script_run
[2024-05-28T07:08:23.145312Z] [debug] [pid:63652] <<< testapi::type_string(string="; echo YpuUt-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:08:24.259156Z] [debug] [pid:63652] tests/autoyast/console.pm:22 called testapi::select_console -> lib/susedistribution.pm:933 called distribution::script_run
[2024-05-28T07:08:24.259399Z] [debug] [pid:63652] <<< testapi::wait_serial(expect_not_found=0, record_output=undef, no_regex=0, regexp=qr/YpuUt-\d+-/u, quiet=undef, timeout=30, buffer_size=undef)
[32m[2024-05-28T07:08:25.314856Z] [debug] [pid:63652] >>> testapi::wait_serial: (?^u:YpuUt-\d+-): ok[0m
[2024-05-28T07:08:25.315138Z] [debug] [pid:63652] tests/autoyast/console.pm:22 called testapi::select_console -> lib/susedistribution.pm:997 called testapi::assert_screen
[2024-05-28T07:08:25.315250Z] [debug] [pid:63652] <<< testapi::assert_screen(mustmatch="root-console", no_wait=1, timeout=30)
[32m[2024-05-28T07:08:25.364369Z] [debug] [pid:63652] >>> testapi::_handle_found_needle: found root-console-20180724, similarity 1.00 @ 80/160[0m
[1;34m[2024-05-28T07:08:25.407624Z] [debug] [pid:63652] ||| finished console autoyast (runtime: 10 s)[0m
[1;34m[2024-05-28T07:08:25.408908Z] [debug] [pid:63652] ||| starting login tests/autoyast/login.pm[0m
[2024-05-28T07:08:25.409547Z] [debug] [pid:63652] tests/autoyast/login.pm:18 called testapi::assert_screen
[2024-05-28T07:08:25.409675Z] [debug] [pid:63652] <<< testapi::assert_screen(mustmatch="autoyast-system-login-console", timeout=20)
[32m[2024-05-28T07:08:26.369371Z] [debug] [pid:63652] >>> testapi::_handle_found_needle: found autoyast-system-login-console-20161014, similarity 1.00 @ 66/98[0m
[2024-05-28T07:08:26.369538Z] [debug] [pid:63652] tests/autoyast/login.pm:28 called testapi::assert_script_run
[2024-05-28T07:08:26.369659Z] [debug] [pid:63652] <<< testapi::assert_script_run(cmd="echo \"checking serial port\"", timeout=90, quiet=undef, fail_message="")
[2024-05-28T07:08:26.369772Z] [debug] [pid:63652] tests/autoyast/login.pm:28 called testapi::assert_script_run
[2024-05-28T07:08:26.369874Z] [debug] [pid:63652] <<< testapi::type_string(string="echo \"checking serial port\"", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:08:27.312766Z] [debug] [pid:63652] tests/autoyast/login.pm:28 called testapi::assert_script_run
[2024-05-28T07:08:27.312966Z] [debug] [pid:63652] <<< testapi::type_string(string="; echo ZbQbF-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:08:28.441773Z] [debug] [pid:63652] tests/autoyast/login.pm:28 called testapi::assert_script_run
[2024-05-28T07:08:28.441992Z] [debug] [pid:63652] <<< testapi::wait_serial(expect_not_found=0, timeout=90, quiet=undef, regexp=qr/ZbQbF-\d+-/u, no_regex=0, record_output=undef, buffer_size=undef)
[32m[2024-05-28T07:08:29.487781Z] [debug] [pid:63652] >>> testapi::wait_serial: (?^u:ZbQbF-\d+-): ok[0m
[2024-05-28T07:08:29.487948Z] [debug] [pid:63652] tests/autoyast/login.pm:29 called testapi::enter_cmd
[2024-05-28T07:08:29.488101Z] [debug] [pid:63652] <<< testapi::type_string(string="cat /proc/cmdline\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[1;34m[2024-05-28T07:08:30.190805Z] [debug] [pid:63652] ||| finished login autoyast (runtime: 5 s)[0m
[1;34m[2024-05-28T07:08:30.191567Z] [debug] [pid:63652] ||| starting verify_btrfs_quota tests/autoyast/verify_btrfs_quota.pm[0m
[2024-05-28T07:08:30.192216Z] [debug] [pid:63652] tests/autoyast/verify_btrfs_quota.pm:22 called testapi::script_output
[2024-05-28T07:08:30.192363Z] [debug] [pid:63652] <<< testapi::type_string(string="cat - > /tmp/script4u9vI.sh;", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:08:31.171074Z] [debug] [pid:63652] tests/autoyast/verify_btrfs_quota.pm:22 called testapi::script_output
[2024-05-28T07:08:31.171378Z] [debug] [pid:63652] <<< testapi::type_string(string="\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:08:31.206042Z] [debug] [pid:63652] tests/autoyast/verify_btrfs_quota.pm:22 called testapi::script_output
[2024-05-28T07:08:31.206200Z] [debug] [pid:63652] <<< testapi::type_string(string="btrfs subvolume list /\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:08:31.984120Z] [debug] [pid:63652] tests/autoyast/verify_btrfs_quota.pm:22 called testapi::script_output
[2024-05-28T07:08:31.984279Z] [debug] [pid:63652] <<< testapi::send_key(key="ctrl-d", wait_screen_change=0)
[2024-05-28T07:08:32.319471Z] [debug] [pid:63652] tests/autoyast/verify_btrfs_quota.pm:22 called testapi::script_output
[2024-05-28T07:08:32.319761Z] [debug] [pid:63652] <<< testapi::type_string(string="(echo 4u9vI; bash -eox pipefail /tmp/script4u9vI.sh ; echo SCRIPT_FINISHED4u9vI-\$?-) | tee /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:08:36.169667Z] [debug] [pid:63652] tests/autoyast/verify_btrfs_quota.pm:22 called testapi::script_output
[2024-05-28T07:08:36.170013Z] [debug] [pid:63652] <<< testapi::wait_serial(quiet=undef, timeout=90, regexp="SCRIPT_FINISHED4u9vI-\\d+-", no_regex=0, record_output=1, expect_not_found=0, buffer_size=undef)
[32m[2024-05-28T07:08:37.215121Z] [debug] [pid:63652] >>> testapi::wait_serial: SCRIPT_FINISHED4u9vI-\d+-: ok[0m
[2024-05-28T07:08:37.215577Z] [debug] [pid:63652] tests/autoyast/verify_btrfs_quota.pm:24 called testapi::script_output
[2024-05-28T07:08:37.215803Z] [debug] [pid:63652] <<< testapi::type_string(string="cat - > /tmp/scriptkYFYJ.sh;", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:08:38.245363Z] [debug] [pid:63652] tests/autoyast/verify_btrfs_quota.pm:24 called testapi::script_output
[2024-05-28T07:08:38.245584Z] [debug] [pid:63652] <<< testapi::type_string(string="\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:08:38.280118Z] [debug] [pid:63652] tests/autoyast/verify_btrfs_quota.pm:24 called testapi::script_output
[2024-05-28T07:08:38.280279Z] [debug] [pid:63652] <<< testapi::type_string(string="btrfs qgroup show -r / | awk '{print \$1,\$4}'\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:08:39.882482Z] [debug] [pid:63652] tests/autoyast/verify_btrfs_quota.pm:24 called testapi::script_output
[2024-05-28T07:08:39.882636Z] [debug] [pid:63652] <<< testapi::send_key(key="ctrl-d", wait_screen_change=0)
[2024-05-28T07:08:40.217851Z] [debug] [pid:63652] tests/autoyast/verify_btrfs_quota.pm:24 called testapi::script_output
[2024-05-28T07:08:40.218284Z] [debug] [pid:63652] <<< testapi::type_string(string="(echo kYFYJ; bash -eox pipefail /tmp/scriptkYFYJ.sh ; echo SCRIPT_FINISHEDkYFYJ-\$?-) | tee /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:08:44.212814Z] [debug] [pid:63652] tests/autoyast/verify_btrfs_quota.pm:24 called testapi::script_output
[2024-05-28T07:08:44.213067Z] [debug] [pid:63652] <<< testapi::wait_serial(expect_not_found=0, record_output=1, no_regex=0, regexp="SCRIPT_FINISHEDkYFYJ-\\d+-", quiet=undef, timeout=90, buffer_size=undef)
[32m[2024-05-28T07:08:46.268539Z] [debug] [pid:63652] >>> testapi::wait_serial: SCRIPT_FINISHEDkYFYJ-\d+-: ok[0m
Use of uninitialized value in regexp compilation at opensuse/tests/autoyast/verify_btrfs_quota.pm line 27.
	verify_btrfs_quota::run(verify_btrfs_quota=HASH(0x5597feb6dc00)) called at /usr/lib/os-autoinst/basetest.pm line 352
	eval {...} called at /usr/lib/os-autoinst/basetest.pm line 346
	basetest::runtest(verify_btrfs_quota=HASH(0x5597feb6dc00)) called at /usr/lib/os-autoinst/autotest.pm line 416
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 416
	autotest::runalltests() called at /usr/lib/os-autoinst/autotest.pm line 273
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 273
	autotest::run_all() called at /usr/lib/os-autoinst/autotest.pm line 324
	autotest::__ANON__(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	eval {...} called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	Mojo::IOLoop::ReadWriteProcess::_fork(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310), CODE(0x5597feaf7790)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 492
	Mojo::IOLoop::ReadWriteProcess::start(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310)) called at /usr/lib/os-autoinst/autotest.pm line 326
	autotest::start_process() called at /usr/lib/os-autoinst/OpenQA/Isotovideo/Runner.pm line 103
	OpenQA::Isotovideo::Runner::start_autotest(OpenQA::Isotovideo::Runner=HASH(0x5597f74906c0)) called at /usr/bin/isotovideo line 172
	eval {...} called at /usr/bin/isotovideo line 161
Use of uninitialized value in concatenation (.) or string at opensuse/tests/autoyast/verify_btrfs_quota.pm line 30.
	verify_btrfs_quota::run(verify_btrfs_quota=HASH(0x5597feb6dc00)) called at /usr/lib/os-autoinst/basetest.pm line 352
	eval {...} called at /usr/lib/os-autoinst/basetest.pm line 346
	basetest::runtest(verify_btrfs_quota=HASH(0x5597feb6dc00)) called at /usr/lib/os-autoinst/autotest.pm line 416
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 416
	autotest::runalltests() called at /usr/lib/os-autoinst/autotest.pm line 273
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 273
	autotest::run_all() called at /usr/lib/os-autoinst/autotest.pm line 324
	autotest::__ANON__(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	eval {...} called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	Mojo::IOLoop::ReadWriteProcess::_fork(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310), CODE(0x5597feaf7790)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 492
	Mojo::IOLoop::ReadWriteProcess::start(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310)) called at /usr/lib/os-autoinst/autotest.pm line 326
	autotest::start_process() called at /usr/lib/os-autoinst/OpenQA/Isotovideo/Runner.pm line 103
	OpenQA::Isotovideo::Runner::start_autotest(OpenQA::Isotovideo::Runner=HASH(0x5597f74906c0)) called at /usr/bin/isotovideo line 172
	eval {...} called at /usr/bin/isotovideo line 161
Use of uninitialized value in regexp compilation at opensuse/tests/autoyast/verify_btrfs_quota.pm line 27.
	verify_btrfs_quota::run(verify_btrfs_quota=HASH(0x5597feb6dc00)) called at /usr/lib/os-autoinst/basetest.pm line 352
	eval {...} called at /usr/lib/os-autoinst/basetest.pm line 346
	basetest::runtest(verify_btrfs_quota=HASH(0x5597feb6dc00)) called at /usr/lib/os-autoinst/autotest.pm line 416
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 416
	autotest::runalltests() called at /usr/lib/os-autoinst/autotest.pm line 273
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 273
	autotest::run_all() called at /usr/lib/os-autoinst/autotest.pm line 324
	autotest::__ANON__(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	eval {...} called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	Mojo::IOLoop::ReadWriteProcess::_fork(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310), CODE(0x5597feaf7790)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 492
	Mojo::IOLoop::ReadWriteProcess::start(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310)) called at /usr/lib/os-autoinst/autotest.pm line 326
	autotest::start_process() called at /usr/lib/os-autoinst/OpenQA/Isotovideo/Runner.pm line 103
	OpenQA::Isotovideo::Runner::start_autotest(OpenQA::Isotovideo::Runner=HASH(0x5597f74906c0)) called at /usr/bin/isotovideo line 172
	eval {...} called at /usr/bin/isotovideo line 161
Use of uninitialized value in concatenation (.) or string at opensuse/tests/autoyast/verify_btrfs_quota.pm line 30.
	verify_btrfs_quota::run(verify_btrfs_quota=HASH(0x5597feb6dc00)) called at /usr/lib/os-autoinst/basetest.pm line 352
	eval {...} called at /usr/lib/os-autoinst/basetest.pm line 346
	basetest::runtest(verify_btrfs_quota=HASH(0x5597feb6dc00)) called at /usr/lib/os-autoinst/autotest.pm line 416
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 416
	autotest::runalltests() called at /usr/lib/os-autoinst/autotest.pm line 273
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 273
	autotest::run_all() called at /usr/lib/os-autoinst/autotest.pm line 324
	autotest::__ANON__(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	eval {...} called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	Mojo::IOLoop::ReadWriteProcess::_fork(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310), CODE(0x5597feaf7790)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 492
	Mojo::IOLoop::ReadWriteProcess::start(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310)) called at /usr/lib/os-autoinst/autotest.pm line 326
	autotest::start_process() called at /usr/lib/os-autoinst/OpenQA/Isotovideo/Runner.pm line 103
	OpenQA::Isotovideo::Runner::start_autotest(OpenQA::Isotovideo::Runner=HASH(0x5597f74906c0)) called at /usr/bin/isotovideo line 172
	eval {...} called at /usr/bin/isotovideo line 161
Use of uninitialized value in regexp compilation at opensuse/tests/autoyast/verify_btrfs_quota.pm line 27.
	verify_btrfs_quota::run(verify_btrfs_quota=HASH(0x5597feb6dc00)) called at /usr/lib/os-autoinst/basetest.pm line 352
	eval {...} called at /usr/lib/os-autoinst/basetest.pm line 346
	basetest::runtest(verify_btrfs_quota=HASH(0x5597feb6dc00)) called at /usr/lib/os-autoinst/autotest.pm line 416
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 416
	autotest::runalltests() called at /usr/lib/os-autoinst/autotest.pm line 273
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 273
	autotest::run_all() called at /usr/lib/os-autoinst/autotest.pm line 324
	autotest::__ANON__(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	eval {...} called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	Mojo::IOLoop::ReadWriteProcess::_fork(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310), CODE(0x5597feaf7790)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 492
	Mojo::IOLoop::ReadWriteProcess::start(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310)) called at /usr/lib/os-autoinst/autotest.pm line 326
	autotest::start_process() called at /usr/lib/os-autoinst/OpenQA/Isotovideo/Runner.pm line 103
	OpenQA::Isotovideo::Runner::start_autotest(OpenQA::Isotovideo::Runner=HASH(0x5597f74906c0)) called at /usr/bin/isotovideo line 172
	eval {...} called at /usr/bin/isotovideo line 161
Use of uninitialized value in concatenation (.) or string at opensuse/tests/autoyast/verify_btrfs_quota.pm line 30.
	verify_btrfs_quota::run(verify_btrfs_quota=HASH(0x5597feb6dc00)) called at /usr/lib/os-autoinst/basetest.pm line 352
	eval {...} called at /usr/lib/os-autoinst/basetest.pm line 346
	basetest::runtest(verify_btrfs_quota=HASH(0x5597feb6dc00)) called at /usr/lib/os-autoinst/autotest.pm line 416
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 416
	autotest::runalltests() called at /usr/lib/os-autoinst/autotest.pm line 273
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 273
	autotest::run_all() called at /usr/lib/os-autoinst/autotest.pm line 324
	autotest::__ANON__(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	eval {...} called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	Mojo::IOLoop::ReadWriteProcess::_fork(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310), CODE(0x5597feaf7790)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 492
	Mojo::IOLoop::ReadWriteProcess::start(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310)) called at /usr/lib/os-autoinst/autotest.pm line 326
	autotest::start_process() called at /usr/lib/os-autoinst/OpenQA/Isotovideo/Runner.pm line 103
	OpenQA::Isotovideo::Runner::start_autotest(OpenQA::Isotovideo::Runner=HASH(0x5597f74906c0)) called at /usr/bin/isotovideo line 172
	eval {...} called at /usr/bin/isotovideo line 161
Use of uninitialized value in regexp compilation at opensuse/tests/autoyast/verify_btrfs_quota.pm line 27.
	verify_btrfs_quota::run(verify_btrfs_quota=HASH(0x5597feb6dc00)) called at /usr/lib/os-autoinst/basetest.pm line 352
	eval {...} called at /usr/lib/os-autoinst/basetest.pm line 346
	basetest::runtest(verify_btrfs_quota=HASH(0x5597feb6dc00)) called at /usr/lib/os-autoinst/autotest.pm line 416
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 416
	autotest::runalltests() called at /usr/lib/os-autoinst/autotest.pm line 273
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 273
	autotest::run_all() called at /usr/lib/os-autoinst/autotest.pm line 324
	autotest::__ANON__(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	eval {...} called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	Mojo::IOLoop::ReadWriteProcess::_fork(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310), CODE(0x5597feaf7790)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 492
	Mojo::IOLoop::ReadWriteProcess::start(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310)) called at /usr/lib/os-autoinst/autotest.pm line 326
	autotest::start_process() called at /usr/lib/os-autoinst/OpenQA/Isotovideo/Runner.pm line 103
	OpenQA::Isotovideo::Runner::start_autotest(OpenQA::Isotovideo::Runner=HASH(0x5597f74906c0)) called at /usr/bin/isotovideo line 172
	eval {...} called at /usr/bin/isotovideo line 161
Use of uninitialized value in concatenation (.) or string at opensuse/tests/autoyast/verify_btrfs_quota.pm line 30.
	verify_btrfs_quota::run(verify_btrfs_quota=HASH(0x5597feb6dc00)) called at /usr/lib/os-autoinst/basetest.pm line 352
	eval {...} called at /usr/lib/os-autoinst/basetest.pm line 346
	basetest::runtest(verify_btrfs_quota=HASH(0x5597feb6dc00)) called at /usr/lib/os-autoinst/autotest.pm line 416
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 416
	autotest::runalltests() called at /usr/lib/os-autoinst/autotest.pm line 273
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 273
	autotest::run_all() called at /usr/lib/os-autoinst/autotest.pm line 324
	autotest::__ANON__(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	eval {...} called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	Mojo::IOLoop::ReadWriteProcess::_fork(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310), CODE(0x5597feaf7790)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 492
	Mojo::IOLoop::ReadWriteProcess::start(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310)) called at /usr/lib/os-autoinst/autotest.pm line 326
	autotest::start_process() called at /usr/lib/os-autoinst/OpenQA/Isotovideo/Runner.pm line 103
	OpenQA::Isotovideo::Runner::start_autotest(OpenQA::Isotovideo::Runner=HASH(0x5597f74906c0)) called at /usr/bin/isotovideo line 172
	eval {...} called at /usr/bin/isotovideo line 161
Use of uninitialized value in regexp compilation at opensuse/tests/autoyast/verify_btrfs_quota.pm line 27.
	verify_btrfs_quota::run(verify_btrfs_quota=HASH(0x5597feb6dc00)) called at /usr/lib/os-autoinst/basetest.pm line 352
	eval {...} called at /usr/lib/os-autoinst/basetest.pm line 346
	basetest::runtest(verify_btrfs_quota=HASH(0x5597feb6dc00)) called at /usr/lib/os-autoinst/autotest.pm line 416
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 416
	autotest::runalltests() called at /usr/lib/os-autoinst/autotest.pm line 273
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 273
	autotest::run_all() called at /usr/lib/os-autoinst/autotest.pm line 324
	autotest::__ANON__(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	eval {...} called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	Mojo::IOLoop::ReadWriteProcess::_fork(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310), CODE(0x5597feaf7790)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 492
	Mojo::IOLoop::ReadWriteProcess::start(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310)) called at /usr/lib/os-autoinst/autotest.pm line 326
	autotest::start_process() called at /usr/lib/os-autoinst/OpenQA/Isotovideo/Runner.pm line 103
	OpenQA::Isotovideo::Runner::start_autotest(OpenQA::Isotovideo::Runner=HASH(0x5597f74906c0)) called at /usr/bin/isotovideo line 172
	eval {...} called at /usr/bin/isotovideo line 161
Use of uninitialized value in concatenation (.) or string at opensuse/tests/autoyast/verify_btrfs_quota.pm line 30.
	verify_btrfs_quota::run(verify_btrfs_quota=HASH(0x5597feb6dc00)) called at /usr/lib/os-autoinst/basetest.pm line 352
	eval {...} called at /usr/lib/os-autoinst/basetest.pm line 346
	basetest::runtest(verify_btrfs_quota=HASH(0x5597feb6dc00)) called at /usr/lib/os-autoinst/autotest.pm line 416
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 416
	autotest::runalltests() called at /usr/lib/os-autoinst/autotest.pm line 273
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 273
	autotest::run_all() called at /usr/lib/os-autoinst/autotest.pm line 324
	autotest::__ANON__(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	eval {...} called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	Mojo::IOLoop::ReadWriteProcess::_fork(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310), CODE(0x5597feaf7790)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 492
	Mojo::IOLoop::ReadWriteProcess::start(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310)) called at /usr/lib/os-autoinst/autotest.pm line 326
	autotest::start_process() called at /usr/lib/os-autoinst/OpenQA/Isotovideo/Runner.pm line 103
	OpenQA::Isotovideo::Runner::start_autotest(OpenQA::Isotovideo::Runner=HASH(0x5597f74906c0)) called at /usr/bin/isotovideo line 172
	eval {...} called at /usr/bin/isotovideo line 161
Use of uninitialized value in regexp compilation at opensuse/tests/autoyast/verify_btrfs_quota.pm line 27.
	verify_btrfs_quota::run(verify_btrfs_quota=HASH(0x5597feb6dc00)) called at /usr/lib/os-autoinst/basetest.pm line 352
	eval {...} called at /usr/lib/os-autoinst/basetest.pm line 346
	basetest::runtest(verify_btrfs_quota=HASH(0x5597feb6dc00)) called at /usr/lib/os-autoinst/autotest.pm line 416
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 416
	autotest::runalltests() called at /usr/lib/os-autoinst/autotest.pm line 273
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 273
	autotest::run_all() called at /usr/lib/os-autoinst/autotest.pm line 324
	autotest::__ANON__(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	eval {...} called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	Mojo::IOLoop::ReadWriteProcess::_fork(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310), CODE(0x5597feaf7790)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 492
	Mojo::IOLoop::ReadWriteProcess::start(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310)) called at /usr/lib/os-autoinst/autotest.pm line 326
	autotest::start_process() called at /usr/lib/os-autoinst/OpenQA/Isotovideo/Runner.pm line 103
	OpenQA::Isotovideo::Runner::start_autotest(OpenQA::Isotovideo::Runner=HASH(0x5597f74906c0)) called at /usr/bin/isotovideo line 172
	eval {...} called at /usr/bin/isotovideo line 161
Use of uninitialized value in concatenation (.) or string at opensuse/tests/autoyast/verify_btrfs_quota.pm line 30.
	verify_btrfs_quota::run(verify_btrfs_quota=HASH(0x5597feb6dc00)) called at /usr/lib/os-autoinst/basetest.pm line 352
	eval {...} called at /usr/lib/os-autoinst/basetest.pm line 346
	basetest::runtest(verify_btrfs_quota=HASH(0x5597feb6dc00)) called at /usr/lib/os-autoinst/autotest.pm line 416
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 416
	autotest::runalltests() called at /usr/lib/os-autoinst/autotest.pm line 273
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 273
	autotest::run_all() called at /usr/lib/os-autoinst/autotest.pm line 324
	autotest::__ANON__(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	eval {...} called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	Mojo::IOLoop::ReadWriteProcess::_fork(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310), CODE(0x5597feaf7790)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 492
	Mojo::IOLoop::ReadWriteProcess::start(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310)) called at /usr/lib/os-autoinst/autotest.pm line 326
	autotest::start_process() called at /usr/lib/os-autoinst/OpenQA/Isotovideo/Runner.pm line 103
	OpenQA::Isotovideo::Runner::start_autotest(OpenQA::Isotovideo::Runner=HASH(0x5597f74906c0)) called at /usr/bin/isotovideo line 172
	eval {...} called at /usr/bin/isotovideo line 161
[1;34m[2024-05-28T07:08:46.273383Z] [debug] [pid:63652] ||| finished verify_btrfs_quota autoyast (runtime: 16 s)[0m
[1;34m[2024-05-28T07:08:46.274322Z] [debug] [pid:63652] ||| starting repos tests/autoyast/repos.pm[0m
[2024-05-28T07:08:46.274980Z] [debug] [pid:63652] tests/autoyast/repos.pm:22 called testapi::assert_script_run
[2024-05-28T07:08:46.275136Z] [debug] [pid:63652] <<< testapi::assert_script_run(cmd="ip a || ifstatus all", timeout=90, fail_message="", quiet=undef)
[2024-05-28T07:08:46.275259Z] [debug] [pid:63652] tests/autoyast/repos.pm:22 called testapi::assert_script_run
[2024-05-28T07:08:46.275398Z] [debug] [pid:63652] <<< testapi::type_string(string="ip a || ifstatus all", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:08:46.984474Z] [debug] [pid:63652] tests/autoyast/repos.pm:22 called testapi::assert_script_run
[2024-05-28T07:08:46.984736Z] [debug] [pid:63652] <<< testapi::type_string(string="; echo EghIr-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:08:48.097677Z] [debug] [pid:63652] tests/autoyast/repos.pm:22 called testapi::assert_script_run
[2024-05-28T07:08:48.097937Z] [debug] [pid:63652] <<< testapi::wait_serial(buffer_size=undef, regexp=qr/EghIr-\d+-/u, quiet=undef, timeout=90, record_output=undef, no_regex=0, expect_not_found=0)
[32m[2024-05-28T07:08:50.157209Z] [debug] [pid:63652] >>> testapi::wait_serial: (?^u:EghIr-\d+-): ok[0m
[2024-05-28T07:08:50.157505Z] [debug] [pid:63652] tests/autoyast/repos.pm:28 called utils::zypper_enable_install_dvd -> lib/utils.pm:710 called utils::zypper_call -> lib/utils.pm:597 called testapi::script_run
[2024-05-28T07:08:50.157691Z] [debug] [pid:63652] <<< testapi::script_run(cmd="zypper -n ref ; ( exit \${PIPESTATUS[0]} )", timeout=700, die_on_timeout=1, quiet=undef, output="")
[2024-05-28T07:08:50.157819Z] [debug] [pid:63652] tests/autoyast/repos.pm:28 called utils::zypper_enable_install_dvd -> lib/utils.pm:710 called utils::zypper_call -> lib/utils.pm:597 called testapi::script_run
[2024-05-28T07:08:50.157961Z] [debug] [pid:63652] <<< testapi::type_string(string="zypper -n ref ; ( exit \${PIPESTATUS[0]} )", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:08:51.793142Z] [debug] [pid:63652] tests/autoyast/repos.pm:28 called utils::zypper_enable_install_dvd -> lib/utils.pm:710 called utils::zypper_call -> lib/utils.pm:597 called testapi::script_run
[2024-05-28T07:08:51.793440Z] [debug] [pid:63652] <<< testapi::type_string(string="; echo 0aei7-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:08:52.872297Z] [debug] [pid:63652] tests/autoyast/repos.pm:28 called utils::zypper_enable_install_dvd -> lib/utils.pm:710 called utils::zypper_call -> lib/utils.pm:597 called testapi::script_run
[2024-05-28T07:08:52.872562Z] [debug] [pid:63652] <<< testapi::wait_serial(timeout=700, regexp=qr/0aei7-\d+-/u, quiet=undef, no_regex=0, record_output=undef, expect_not_found=0, buffer_size=undef)
[32m[2024-05-28T07:08:54.919141Z] [debug] [pid:63652] >>> testapi::wait_serial: (?^u:0aei7-\d+-): ok[0m
[2024-05-28T07:08:54.919369Z] [debug] [pid:63652] tests/autoyast/repos.pm:31 called utils::zypper_call -> lib/utils.pm:597 called testapi::script_run
[2024-05-28T07:08:54.919506Z] [debug] [pid:63652] <<< testapi::script_run(cmd="zypper -n in yast2 tar bzip2 ; ( exit \${PIPESTATUS[0]} )", output="", die_on_timeout=1, quiet=undef, timeout=700)
[2024-05-28T07:08:54.919598Z] [debug] [pid:63652] tests/autoyast/repos.pm:31 called utils::zypper_call -> lib/utils.pm:597 called testapi::script_run
[2024-05-28T07:08:54.919697Z] [debug] [pid:63652] <<< testapi::type_string(string="zypper -n in yast2 tar bzip2 ; ( exit \${PIPESTATUS[0]} )", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:08:57.060457Z] [debug] [pid:63652] tests/autoyast/repos.pm:31 called utils::zypper_call -> lib/utils.pm:597 called testapi::script_run
[2024-05-28T07:08:57.060668Z] [debug] [pid:63652] <<< testapi::type_string(string="; echo WV4hP-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:08:58.190453Z] [debug] [pid:63652] tests/autoyast/repos.pm:31 called utils::zypper_call -> lib/utils.pm:597 called testapi::script_run
[2024-05-28T07:08:58.190670Z] [debug] [pid:63652] <<< testapi::wait_serial(buffer_size=undef, expect_not_found=0, quiet=undef, timeout=700, regexp=qr/WV4hP-\d+-/u, no_regex=0, record_output=undef)
[32m[2024-05-28T07:09:01.248383Z] [debug] [pid:63652] >>> testapi::wait_serial: (?^u:WV4hP-\d+-): ok[0m
[2024-05-28T07:09:01.248584Z] [debug] [pid:63652] tests/autoyast/repos.pm:32 called testapi::assert_script_run
[2024-05-28T07:09:01.248701Z] [debug] [pid:63652] <<< testapi::assert_script_run(cmd="save_y2logs /tmp/y2logs.tar.bz2", quiet=undef, fail_message="", timeout=90)
[2024-05-28T07:09:01.248792Z] [debug] [pid:63652] tests/autoyast/repos.pm:32 called testapi::assert_script_run
[2024-05-28T07:09:01.248891Z] [debug] [pid:63652] <<< testapi::type_string(string="save_y2logs /tmp/y2logs.tar.bz2", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:09:02.310636Z] [debug] [pid:63652] tests/autoyast/repos.pm:32 called testapi::assert_script_run
[2024-05-28T07:09:02.310846Z] [debug] [pid:63652] <<< testapi::type_string(string="; echo FhAt1-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:09:03.422737Z] [debug] [pid:63652] tests/autoyast/repos.pm:32 called testapi::assert_script_run
[2024-05-28T07:09:03.422964Z] [debug] [pid:63652] <<< testapi::wait_serial(quiet=undef, timeout=90, regexp=qr/FhAt1-\d+-/u, no_regex=0, record_output=undef, expect_not_found=0, buffer_size=undef)
[32m[2024-05-28T07:09:06.482621Z] [debug] [pid:63652] >>> testapi::wait_serial: (?^u:FhAt1-\d+-): ok[0m
[2024-05-28T07:09:06.482864Z] [debug] [pid:63652] tests/autoyast/repos.pm:33 called testapi::upload_logs
[2024-05-28T07:09:06.483014Z] [debug] [pid:63652] <<< testapi::upload_logs(file="/tmp/y2logs.tar.bz2", failok=0, timeout=90)
[2024-05-28T07:09:06.483223Z] [debug] [pid:63652] tests/autoyast/repos.pm:33 called testapi::upload_logs
[2024-05-28T07:09:06.483365Z] [debug] [pid:63652] <<< testapi::assert_script_run(cmd="curl --form upload=\@/tmp/y2logs.tar.bz2 --form upname=repos-y2logs.tar.bz2 http://10.0.2.2:20203/qB7uxifSCr757qLM/uploadlog/y2logs.tar.bz2", quiet=undef, fail_message="", timeout=90)
[2024-05-28T07:09:06.483504Z] [debug] [pid:63652] tests/autoyast/repos.pm:33 called testapi::upload_logs
[2024-05-28T07:09:06.483669Z] [debug] [pid:63652] <<< testapi::type_string(string="curl --form upload=\@/tmp/y2logs.tar.bz2 --form upname=repos-y2logs.tar.bz2 http://10.0.2.2:20203/qB7uxifSCr757qLM/uploadlog/y2logs.tar.bz2", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:09:11.270196Z] [debug] [pid:63652] tests/autoyast/repos.pm:33 called testapi::upload_logs
[2024-05-28T07:09:11.270415Z] [debug] [pid:63652] <<< testapi::type_string(string="; echo UnPnC-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:09:12.398935Z] [debug] [pid:63652] tests/autoyast/repos.pm:33 called testapi::upload_logs
[2024-05-28T07:09:12.399157Z] [debug] [pid:63652] <<< testapi::wait_serial(buffer_size=undef, expect_not_found=0, timeout=90, quiet=undef, regexp=qr/UnPnC-\d+-/u, record_output=undef, no_regex=0)
[32m[2024-05-28T07:09:15.448851Z] [debug] [pid:63652] >>> testapi::wait_serial: (?^u:UnPnC-\d+-): ok[0m
[2024-05-28T07:09:15.449101Z] [debug] [pid:63652] lib/y2_module_consoletest.pm:57 called opensusebasetest::clear_and_verify_console -> lib/opensusebasetest.pm:53 called utils::clear_console -> lib/utils.pm:387 called testapi::enter_cmd
[2024-05-28T07:09:15.449266Z] [debug] [pid:63652] <<< testapi::type_string(string="clear\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:09:15.652254Z] [debug] [pid:63652] lib/y2_module_consoletest.pm:57 called opensusebasetest::clear_and_verify_console -> lib/opensusebasetest.pm:54 called testapi::assert_screen
[2024-05-28T07:09:15.652372Z] [debug] [pid:63652] <<< testapi::assert_screen(mustmatch="cleared-console", timeout=30)
[37m[2024-05-28T07:09:15.712706Z] [debug] [pid:63842] no match: 29.9s, best candidate: cleared-console-20141130 (0.00)[0m
[32m[2024-05-28T07:09:16.742690Z] [debug] [pid:63652] >>> testapi::_handle_found_needle: found cleared-console-standard_prompt-20191207, similarity 1.00 @ 66/1[0m
[1;34m[2024-05-28T07:09:16.743164Z] [debug] [pid:63652] ||| finished repos autoyast (runtime: 30 s)[0m
[1;34m[2024-05-28T07:09:16.744040Z] [debug] [pid:63652] ||| starting clone tests/autoyast/clone.pm[0m
[2024-05-28T07:09:16.744616Z] [debug] [pid:63652] tests/autoyast/clone.pm:20 called testapi::assert_script_run
[2024-05-28T07:09:16.744739Z] [debug] [pid:63652] <<< testapi::assert_script_run(cmd="rm -f /root/autoinst.xml", quiet=undef, timeout=90, fail_message="")
[2024-05-28T07:09:16.744837Z] [debug] [pid:63652] tests/autoyast/clone.pm:20 called testapi::assert_script_run
[2024-05-28T07:09:16.744931Z] [debug] [pid:63652] <<< testapi::type_string(string="rm -f /root/autoinst.xml", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:09:17.553707Z] [debug] [pid:63652] tests/autoyast/clone.pm:20 called testapi::assert_script_run
[2024-05-28T07:09:17.553908Z] [debug] [pid:63652] <<< testapi::type_string(string="; echo zQ81W-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:09:18.666769Z] [debug] [pid:63652] tests/autoyast/clone.pm:20 called testapi::assert_script_run
[2024-05-28T07:09:18.667037Z] [debug] [pid:63652] <<< testapi::wait_serial(buffer_size=undef, expect_not_found=0, quiet=undef, regexp=qr/zQ81W-\d+-/u, timeout=90, no_regex=0, record_output=undef)
[32m[2024-05-28T07:09:19.714385Z] [debug] [pid:63652] >>> testapi::wait_serial: (?^u:zQ81W-\d+-): ok[0m
Odd number of elements in hash assignment at opensuse/lib/utils.pm line 579.
	utils::zypper_call("in autoyast2", 300) called at opensuse/tests/autoyast/clone.pm line 21
	clone::run(clone=HASH(0x5597fe74b160)) called at /usr/lib/os-autoinst/basetest.pm line 352
	eval {...} called at /usr/lib/os-autoinst/basetest.pm line 346
	basetest::runtest(clone=HASH(0x5597fe74b160)) called at /usr/lib/os-autoinst/autotest.pm line 416
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 416
	autotest::runalltests() called at /usr/lib/os-autoinst/autotest.pm line 273
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 273
	autotest::run_all() called at /usr/lib/os-autoinst/autotest.pm line 324
	autotest::__ANON__(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	eval {...} called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	Mojo::IOLoop::ReadWriteProcess::_fork(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310), CODE(0x5597feaf7790)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 492
	Mojo::IOLoop::ReadWriteProcess::start(Mojo::IOLoop::ReadWriteProcess=HASH(0x5597ffdea310)) called at /usr/lib/os-autoinst/autotest.pm line 326
	autotest::start_process() called at /usr/lib/os-autoinst/OpenQA/Isotovideo/Runner.pm line 103
	OpenQA::Isotovideo::Runner::start_autotest(OpenQA::Isotovideo::Runner=HASH(0x5597f74906c0)) called at /usr/bin/isotovideo line 172
	eval {...} called at /usr/bin/isotovideo line 161
[2024-05-28T07:09:19.714906Z] [debug] [pid:63652] tests/autoyast/clone.pm:21 called utils::zypper_call -> lib/utils.pm:597 called testapi::script_run
[2024-05-28T07:09:19.715039Z] [debug] [pid:63652] <<< testapi::script_run(cmd="zypper -n in autoyast2 ; ( exit \${PIPESTATUS[0]} )", output="", quiet=undef, die_on_timeout=1, timeout=700)
[2024-05-28T07:09:19.715136Z] [debug] [pid:63652] tests/autoyast/clone.pm:21 called utils::zypper_call -> lib/utils.pm:597 called testapi::script_run
[2024-05-28T07:09:19.715232Z] [debug] [pid:63652] <<< testapi::type_string(string="zypper -n in autoyast2 ; ( exit \${PIPESTATUS[0]} )", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:09:21.654833Z] [debug] [pid:63652] tests/autoyast/clone.pm:21 called utils::zypper_call -> lib/utils.pm:597 called testapi::script_run
[2024-05-28T07:09:21.655050Z] [debug] [pid:63652] <<< testapi::type_string(string="; echo N5Pyk-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:09:22.768723Z] [debug] [pid:63652] tests/autoyast/clone.pm:21 called utils::zypper_call -> lib/utils.pm:597 called testapi::script_run
[2024-05-28T07:09:22.769025Z] [debug] [pid:63652] <<< testapi::wait_serial(expect_not_found=0, record_output=undef, no_regex=0, regexp=qr/N5Pyk-\d+-/u, timeout=700, quiet=undef, buffer_size=undef)
[32m[2024-05-28T07:09:24.815369Z] [debug] [pid:63652] >>> testapi::wait_serial: (?^u:N5Pyk-\d+-): ok[0m
[2024-05-28T07:09:24.815608Z] [debug] [pid:63652] tests/autoyast/clone.pm:22 called y2_module_consoletest::yast2_console_exec -> lib/y2_module_consoletest.pm:37 called testapi::script_run
[2024-05-28T07:09:24.815736Z] [debug] [pid:63652] <<< testapi::script_run(cmd="Y2DEBUG=1 ZYPP_MEDIA_CURL_DEBUG=1 Y2STRICTTEXTDOMAIN=1  yast2 --ncurses clone_system; echo yast2-clone_system-status-\$? > /dev/ttyS0", timeout=0, quiet=undef, die_on_timeout=1, output="")
[2024-05-28T07:09:24.815841Z] [debug] [pid:63652] tests/autoyast/clone.pm:22 called y2_module_consoletest::yast2_console_exec -> lib/y2_module_consoletest.pm:37 called testapi::script_run
[2024-05-28T07:09:24.815945Z] [debug] [pid:63652] <<< testapi::type_string(string="Y2DEBUG=1 ZYPP_MEDIA_CURL_DEBUG=1 Y2STRICTTEXTDOMAIN=1  yast2 --ncurses clone_system; echo yast2-clone_system-status-\$? > /dev/ttyS0", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:09:30.107507Z] [debug] [pid:63652] tests/autoyast/clone.pm:22 called y2_module_consoletest::yast2_console_exec -> lib/y2_module_consoletest.pm:37 called testapi::script_run
[2024-05-28T07:09:30.107680Z] [debug] [pid:63652] <<< testapi::send_key(key="ret", wait_screen_change=0)
[2024-05-28T07:09:30.375896Z] [debug] [pid:63652] tests/autoyast/clone.pm:23 called testapi::check_screen
[2024-05-28T07:09:30.376079Z] [debug] [pid:63652] <<< testapi::check_screen(mustmatch="autoyast2-install-accept", timeout=10)
[33m[2024-05-28T07:09:30.376665Z] [info] [pid:63842] ::: backend::baseclass::set_tags_to_assert: NO matching needles for autoyast2-install-accept[0m
[37m[2024-05-28T07:09:30.377015Z] [debug] [pid:63842] no match: 9.9s[0m
[37m[2024-05-28T07:09:31.378348Z] [debug] [pid:63842] no match: 8.9s[0m
[37m[2024-05-28T07:09:32.379507Z] [debug] [pid:63842] no match: 7.9s[0m
[37m[2024-05-28T07:09:33.380626Z] [debug] [pid:63842] no change: 6.9s[0m
[37m[2024-05-28T07:09:33.380838Z] [debug] [pid:63842] no match: 6.9s[0m
[37m[2024-05-28T07:09:34.381813Z] [debug] [pid:63842] no match: 5.9s[0m
[37m[2024-05-28T07:09:35.382811Z] [debug] [pid:63842] no change: 4.9s[0m
[37m[2024-05-28T07:09:35.383005Z] [debug] [pid:63842] no match: 4.9s[0m
[37m[2024-05-28T07:09:36.383911Z] [debug] [pid:63842] no change: 3.9s[0m
[37m[2024-05-28T07:09:36.384123Z] [debug] [pid:63842] no match: 3.9s[0m
[37m[2024-05-28T07:09:37.385028Z] [debug] [pid:63842] no change: 2.9s[0m
[37m[2024-05-28T07:09:37.385163Z] [debug] [pid:63842] no match: 2.9s[0m
[37m[2024-05-28T07:09:38.386140Z] [debug] [pid:63842] no change: 1.9s[0m
[37m[2024-05-28T07:09:38.386372Z] [debug] [pid:63842] no match: 1.9s[0m
[37m[2024-05-28T07:09:39.387233Z] [debug] [pid:63842] no match: 0.9s[0m
[37m[2024-05-28T07:09:40.388269Z] [debug] [pid:63842] no match: -0.1s[0m
[32m[2024-05-28T07:09:40.472842Z] [debug] [pid:63652] >>> testapi::_check_backend_response: match=autoyast2-install-accept timed out after 10 (check_screen)[0m
[2024-05-28T07:09:40.484892Z] [debug] [pid:63652] tests/autoyast/clone.pm:28 called testapi::wait_serial
[2024-05-28T07:09:40.485049Z] [debug] [pid:63652] <<< testapi::wait_serial(no_regex=0, record_output=undef, regexp="yast2-clone_system-status-0", quiet=undef, timeout=1400, expect_not_found=0, buffer_size=undef)
[32m[2024-05-28T07:09:52.531924Z] [debug] [pid:63652] >>> testapi::wait_serial: yast2-clone_system-status-0: ok[0m
[2024-05-28T07:09:52.532087Z] [debug] [pid:63652] tests/autoyast/clone.pm:29 called testapi::upload_logs
[2024-05-28T07:09:52.532203Z] [debug] [pid:63652] <<< testapi::upload_logs(file="/root/autoinst.xml", failok=0, timeout=90)
[2024-05-28T07:09:52.532340Z] [debug] [pid:63652] tests/autoyast/clone.pm:29 called testapi::upload_logs
[2024-05-28T07:09:52.532429Z] [debug] [pid:63652] <<< testapi::assert_script_run(cmd="curl --form upload=\@/root/autoinst.xml --form upname=clone-autoinst.xml http://10.0.2.2:20203/qB7uxifSCr757qLM/uploadlog/autoinst.xml", quiet=undef, fail_message="", timeout=90)
[2024-05-28T07:09:52.532529Z] [debug] [pid:63652] tests/autoyast/clone.pm:29 called testapi::upload_logs
[2024-05-28T07:09:52.532629Z] [debug] [pid:63652] <<< testapi::type_string(string="curl --form upload=\@/root/autoinst.xml --form upname=clone-autoinst.xml http://10.0.2.2:20203/qB7uxifSCr757qLM/uploadlog/autoinst.xml", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:09:57.148025Z] [debug] [pid:63652] tests/autoyast/clone.pm:29 called testapi::upload_logs
[2024-05-28T07:09:57.148254Z] [debug] [pid:63652] <<< testapi::type_string(string="; echo 0QeNx-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:09:58.259711Z] [debug] [pid:63652] tests/autoyast/clone.pm:29 called testapi::upload_logs
[2024-05-28T07:09:58.259946Z] [debug] [pid:63652] <<< testapi::wait_serial(buffer_size=undef, no_regex=0, record_output=undef, quiet=undef, regexp=qr/0QeNx-\d+-/u, timeout=90, expect_not_found=0)
[32m[2024-05-28T07:09:59.301528Z] [debug] [pid:63652] >>> testapi::wait_serial: (?^u:0QeNx-\d+-): ok[0m
[2024-05-28T07:09:59.301685Z] [debug] [pid:63652] tests/autoyast/clone.pm:32 called testapi::upload_logs
[2024-05-28T07:09:59.301787Z] [debug] [pid:63652] <<< testapi::upload_logs(file="/var/adm/autoinstall/cache/installedSystem.xml", failok=0, timeout=90)
[2024-05-28T07:09:59.301918Z] [debug] [pid:63652] tests/autoyast/clone.pm:32 called testapi::upload_logs
[2024-05-28T07:09:59.302006Z] [debug] [pid:63652] <<< testapi::assert_script_run(cmd="curl --form upload=\@/var/adm/autoinstall/cache/installedSystem.xml --form upname=clone-installedSystem.xml http://10.0.2.2:20203/qB7uxifSCr757qLM/uploadlog/installedSystem.xml", quiet=undef, timeout=90, fail_message="")
[2024-05-28T07:09:59.302095Z] [debug] [pid:63652] tests/autoyast/clone.pm:32 called testapi::upload_logs
[2024-05-28T07:09:59.302194Z] [debug] [pid:63652] <<< testapi::type_string(string="curl --form upload=\@/var/adm/autoinstall/cache/installedSystem.xml --form upname=clone-installedSystem.xml http://10.0.2.2:20203/qB7uxifSCr757qLM/uploadlog/installedSystem.xml", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:10:05.381815Z] [debug] [pid:63652] tests/autoyast/clone.pm:32 called testapi::upload_logs
[2024-05-28T07:10:05.382056Z] [debug] [pid:63652] <<< testapi::type_string(string="; echo LiImr-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:10:06.494028Z] [debug] [pid:63652] tests/autoyast/clone.pm:32 called testapi::upload_logs
[2024-05-28T07:10:06.494259Z] [debug] [pid:63652] <<< testapi::wait_serial(expect_not_found=0, timeout=90, regexp=qr/LiImr-\d+-/u, quiet=undef, no_regex=0, record_output=undef, buffer_size=undef)
[32m[2024-05-28T07:10:08.544974Z] [debug] [pid:63652] >>> testapi::wait_serial: (?^u:LiImr-\d+-): ok[0m
[2024-05-28T07:10:08.545150Z] [debug] [pid:63652] tests/autoyast/clone.pm:33 called testapi::assert_script_run
[2024-05-28T07:10:08.545270Z] [debug] [pid:63652] <<< testapi::assert_script_run(cmd="save_y2logs /tmp/y2logs_clone.tar.bz2", timeout=90, quiet=undef, fail_message="")
[2024-05-28T07:10:08.545367Z] [debug] [pid:63652] tests/autoyast/clone.pm:33 called testapi::assert_script_run
[2024-05-28T07:10:08.545464Z] [debug] [pid:63652] <<< testapi::type_string(string="save_y2logs /tmp/y2logs_clone.tar.bz2", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:10:09.825873Z] [debug] [pid:63652] tests/autoyast/clone.pm:33 called testapi::assert_script_run
[2024-05-28T07:10:09.826069Z] [debug] [pid:63652] <<< testapi::type_string(string="; echo Aw2ws-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:10:10.922133Z] [debug] [pid:63652] tests/autoyast/clone.pm:33 called testapi::assert_script_run
[2024-05-28T07:10:10.922384Z] [debug] [pid:63652] <<< testapi::wait_serial(buffer_size=undef, expect_not_found=0, quiet=undef, timeout=90, regexp=qr/Aw2ws-\d+-/u, record_output=undef, no_regex=0)
[32m[2024-05-28T07:10:13.978398Z] [debug] [pid:63652] >>> testapi::wait_serial: (?^u:Aw2ws-\d+-): ok[0m
[2024-05-28T07:10:13.978592Z] [debug] [pid:63652] tests/autoyast/clone.pm:34 called testapi::upload_logs
[2024-05-28T07:10:13.978724Z] [debug] [pid:63652] <<< testapi::upload_logs(file="/tmp/y2logs_clone.tar.bz2", failok=0, timeout=90)
[2024-05-28T07:10:13.978891Z] [debug] [pid:63652] tests/autoyast/clone.pm:34 called testapi::upload_logs
[2024-05-28T07:10:13.979022Z] [debug] [pid:63652] <<< testapi::assert_script_run(cmd="curl --form upload=\@/tmp/y2logs_clone.tar.bz2 --form upname=clone-y2logs_clone.tar.bz2 http://10.0.2.2:20203/qB7uxifSCr757qLM/uploadlog/y2logs_clone.tar.bz2", timeout=90, fail_message="", quiet=undef)
[2024-05-28T07:10:13.979143Z] [debug] [pid:63652] tests/autoyast/clone.pm:34 called testapi::upload_logs
[2024-05-28T07:10:13.979286Z] [debug] [pid:63652] <<< testapi::type_string(string="curl --form upload=\@/tmp/y2logs_clone.tar.bz2 --form upname=clone-y2logs_clone.tar.bz2 http://10.0.2.2:20203/qB7uxifSCr757qLM/uploadlog/y2logs_clone.tar.bz2", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:10:19.419095Z] [debug] [pid:63652] tests/autoyast/clone.pm:34 called testapi::upload_logs
[2024-05-28T07:10:19.419430Z] [debug] [pid:63652] <<< testapi::type_string(string="; echo uDo3d-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:10:20.514641Z] [debug] [pid:63652] tests/autoyast/clone.pm:34 called testapi::upload_logs
[2024-05-28T07:10:20.514855Z] [debug] [pid:63652] <<< testapi::wait_serial(buffer_size=undef, quiet=undef, regexp=qr/uDo3d-\d+-/u, timeout=90, no_regex=0, record_output=undef, expect_not_found=0)
[32m[2024-05-28T07:10:23.566359Z] [debug] [pid:63652] >>> testapi::wait_serial: (?^u:uDo3d-\d+-): ok[0m
[2024-05-28T07:10:23.628149Z] [debug] [pid:63652] lib/y2_module_consoletest.pm:57 called opensusebasetest::clear_and_verify_console -> lib/opensusebasetest.pm:53 called utils::clear_console -> lib/utils.pm:387 called testapi::enter_cmd
[2024-05-28T07:10:23.628382Z] [debug] [pid:63652] <<< testapi::type_string(string="clear\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:10:23.831747Z] [debug] [pid:63652] lib/y2_module_consoletest.pm:57 called opensusebasetest::clear_and_verify_console -> lib/opensusebasetest.pm:54 called testapi::assert_screen
[2024-05-28T07:10:23.831916Z] [debug] [pid:63652] <<< testapi::assert_screen(mustmatch="cleared-console", timeout=30)
[37m[2024-05-28T07:10:23.881750Z] [debug] [pid:63842] no match: 29.9s, best candidate: cleared-console-20141130 (0.00)[0m
[32m[2024-05-28T07:10:24.949145Z] [debug] [pid:63652] >>> testapi::_handle_found_needle: found cleared-console-standard_prompt-20191207, similarity 1.00 @ 66/1[0m
[1;34m[2024-05-28T07:10:24.949710Z] [debug] [pid:63652] ||| finished clone autoyast (runtime: 68 s)[0m
[1;34m[2024-05-28T07:10:24.950881Z] [debug] [pid:63652] ||| starting verify_cloned_profile tests/autoyast/verify_cloned_profile.pm[0m
[2024-05-28T07:10:24.951515Z] [debug] [pid:63652] tests/autoyast/verify_cloned_profile.pm:18 called autoyast::validate_autoyast_profile -> lib/autoyast.pm:301 called autoyast::init_autoyast_profile -> lib/autoyast.pm:236 called testapi::select_console
[2024-05-28T07:10:24.951605Z] [debug] [pid:63652] <<< testapi::select_console(testapi_console="root-console")
[2024-05-28T07:10:25.357384Z] [debug] [pid:63652] tests/autoyast/verify_cloned_profile.pm:18 called autoyast::validate_autoyast_profile -> lib/autoyast.pm:301 called autoyast::init_autoyast_profile -> lib/autoyast.pm:236 called testapi::select_console -> lib/susedistribution.pm:997 called testapi::assert_screen
[2024-05-28T07:10:25.357631Z] [debug] [pid:63652] <<< testapi::assert_screen(mustmatch="root-console", timeout=30, no_wait=1)
[32m[2024-05-28T07:10:25.444029Z] [debug] [pid:63652] >>> testapi::_handle_found_needle: found root-console-20200501, similarity 0.99 @ 79/1[0m
[2024-05-28T07:10:25.444319Z] [debug] [pid:63652] tests/autoyast/verify_cloned_profile.pm:18 called autoyast::validate_autoyast_profile -> lib/autoyast.pm:301 called autoyast::init_autoyast_profile -> lib/autoyast.pm:239 called testapi::script_run
[2024-05-28T07:10:25.444511Z] [debug] [pid:63652] <<< testapi::script_run(cmd="[ -e /root/autoinst.xml ]", die_on_timeout=1, timeout=30, quiet=undef, output="")
[2024-05-28T07:10:25.444755Z] [debug] [pid:63652] tests/autoyast/verify_cloned_profile.pm:18 called autoyast::validate_autoyast_profile -> lib/autoyast.pm:301 called autoyast::init_autoyast_profile -> lib/autoyast.pm:239 called testapi::script_run
[2024-05-28T07:10:25.444914Z] [debug] [pid:63652] <<< testapi::type_string(string="[ -e /root/autoinst.xml ]", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:10:26.287854Z] [debug] [pid:63652] tests/autoyast/verify_cloned_profile.pm:18 called autoyast::validate_autoyast_profile -> lib/autoyast.pm:301 called autoyast::init_autoyast_profile -> lib/autoyast.pm:239 called testapi::script_run
[2024-05-28T07:10:26.288184Z] [debug] [pid:63652] <<< testapi::type_string(string="; echo pX47O-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:10:27.401457Z] [debug] [pid:63652] tests/autoyast/verify_cloned_profile.pm:18 called autoyast::validate_autoyast_profile -> lib/autoyast.pm:301 called autoyast::init_autoyast_profile -> lib/autoyast.pm:239 called testapi::script_run
[2024-05-28T07:10:27.401738Z] [debug] [pid:63652] <<< testapi::wait_serial(buffer_size=undef, expect_not_found=0, regexp=qr/pX47O-\d+-/u, quiet=undef, timeout=30, no_regex=0, record_output=undef)
[32m[2024-05-28T07:10:28.452786Z] [debug] [pid:63652] >>> testapi::wait_serial: (?^u:pX47O-\d+-): ok[0m
[2024-05-28T07:10:28.452990Z] [debug] [pid:63652] tests/autoyast/verify_cloned_profile.pm:18 called autoyast::validate_autoyast_profile -> lib/autoyast.pm:301 called autoyast::init_autoyast_profile -> lib/autoyast.pm:243 called testapi::script_output
[2024-05-28T07:10:28.453123Z] [debug] [pid:63652] <<< testapi::type_string(string="cat - > /tmp/scriptsx~9G.sh;", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:10:29.448481Z] [debug] [pid:63652] tests/autoyast/verify_cloned_profile.pm:18 called autoyast::validate_autoyast_profile -> lib/autoyast.pm:301 called autoyast::init_autoyast_profile -> lib/autoyast.pm:243 called testapi::script_output
[2024-05-28T07:10:29.448774Z] [debug] [pid:63652] <<< testapi::type_string(string="\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:10:29.483397Z] [debug] [pid:63652] tests/autoyast/verify_cloned_profile.pm:18 called autoyast::validate_autoyast_profile -> lib/autoyast.pm:301 called autoyast::init_autoyast_profile -> lib/autoyast.pm:243 called testapi::script_output
[2024-05-28T07:10:29.483548Z] [debug] [pid:63652] <<< testapi::type_string(string="cat /root/autoinst.xml\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:10:30.258277Z] [debug] [pid:63652] tests/autoyast/verify_cloned_profile.pm:18 called autoyast::validate_autoyast_profile -> lib/autoyast.pm:301 called autoyast::init_autoyast_profile -> lib/autoyast.pm:243 called testapi::script_output
[2024-05-28T07:10:30.258448Z] [debug] [pid:63652] <<< testapi::send_key(key="ctrl-d", wait_screen_change=0)
[2024-05-28T07:10:30.593636Z] [debug] [pid:63652] tests/autoyast/verify_cloned_profile.pm:18 called autoyast::validate_autoyast_profile -> lib/autoyast.pm:301 called autoyast::init_autoyast_profile -> lib/autoyast.pm:243 called testapi::script_output
[2024-05-28T07:10:30.593919Z] [debug] [pid:63652] <<< testapi::type_string(string="(echo sx~9G; bash -eox pipefail /tmp/scriptsx~9G.sh ; echo SCRIPT_FINISHEDsx~9G-\$?-) | tee /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:10:34.491291Z] [debug] [pid:63652] tests/autoyast/verify_cloned_profile.pm:18 called autoyast::validate_autoyast_profile -> lib/autoyast.pm:301 called autoyast::init_autoyast_profile -> lib/autoyast.pm:243 called testapi::script_output
[2024-05-28T07:10:34.491597Z] [debug] [pid:63652] <<< testapi::wait_serial(buffer_size=undef, quiet=undef, timeout=90, regexp="SCRIPT_FINISHEDsx~9G-\\d+-", record_output=1, no_regex=0, expect_not_found=0)
[32m[2024-05-28T07:10:36.548754Z] [debug] [pid:63652] >>> testapi::wait_serial: SCRIPT_FINISHEDsx~9G-\d+-: ok[0m
[2024-05-28T07:10:36.551345Z] [debug] [pid:63652] tests/autoyast/verify_cloned_profile.pm:18 called autoyast::validate_autoyast_profile -> lib/autoyast.pm:306 called testapi::record_info
[2024-05-28T07:10:36.551537Z] [debug] [pid:63652] <<< testapi::record_info(title="Summary", output="Errors found:\nnone\n\nExpressions executed:\n/ns:profile/ns:partitioning/ns:drive/ns:device[text()='/dev/vda']\n/ns:profile/ns:partitioning/ns:drive/ns:enable_snapshots[text()='true' and \@t='boolean']\n/ns:profile/ns:partitioning/ns:drive/ns:partitions/ns:partition[ns:mount[text()='/'] and ns:quotas[text()='true' and \@t='boolean'] and ns:subvolumes[\@t='list' and count(ns:subvolume)=8]]\n/ns:profile/ns:partitioning/ns:drive/ns:partitions/ns:partition[ns:mount[text()='/'] and ns:quotas[text()='true' and \@t='boolean'] and ns:subvolumes[\@t='list' and count(ns:subvolume)=8]]/ns:subvolumes/ns:subvolume[ns:path[text()='var'] and ns:referenced_limit[text()='1 GiB']]\n/ns:profile/ns:partitioning/ns:drive/ns:partitions/ns:partition[ns:mount[text()='/'] and ns:quotas[text()='true' and \@t='boolean'] and ns:subvolumes[\@t='list' and count(ns:subvolume)=8]]/ns:subvolumes/ns:subvolume[ns:path[text()='usr/local'] and ns:referenced_limit[text()='1 GiB']]\n/ns:profile/ns:partitioning/ns:drive/ns:partitions/ns:partition[ns:mount[text()='/'] and ns:quotas[text()='true' and \@t='boolean'] and ns:subvolumes[\@t='list' and count(ns:subvolume)=8]]/ns:subvolumes/ns:subvolume[ns:path[text()='tmp'] and ns:referenced_limit[text()='1 GiB']]\n/ns:profile/ns:partitioning/ns:drive/ns:partitions/ns:partition[ns:mount[text()='/'] and ns:quotas[text()='true' and \@t='boolean'] and ns:subvolumes[\@t='list' and count(ns:subvolume)=8]]/ns:subvolumes/ns:subvolume[ns:path[text()='root'] and ns:referenced_limit[text()='1 GiB']]\n/ns:profile/ns:partitioning/ns:drive/ns:partitions/ns:partition[ns:mount[text()='/'] and ns:quotas[text()='true' and \@t='boolean'] and ns:subvolumes[\@t='list' and count(ns:subvolume)=8]]/ns:subvolumes/ns:subvolume[ns:path[text()='srv'] and ns:referenced_limit[text()='1 GiB']]\n/ns:profile/ns:partitioning/ns:drive/ns:partitions/ns:partition[ns:mount[text()='/'] and ns:quotas[text()='true' and \@t='boolean'] and ns:subvolumes[\@t='list' and count(ns:subvolume)=8]]/ns:subvolumes/ns:subvolume[ns:path[text()='opt'] and ns:referenced_limit[text()='1 GiB']]\n", result="ok")
[1;34m[2024-05-28T07:10:36.559088Z] [debug] [pid:63652] ||| finished verify_cloned_profile autoyast (runtime: 12 s)[0m
[37m[2024-05-28T07:10:36.560756Z] [debug] [pid:63630] stopping autotest process 63652[0m
[37m[2024-05-28T07:10:36.577736Z] [debug] [pid:63630] [autotest] process exited: 0[0m
[37m[2024-05-28T07:10:36.678062Z] [debug] [pid:63630] done with autotest process[0m
[37m[2024-05-28T07:10:36.678397Z] [debug] [pid:63630] stopping command server 63641 because test execution ended[0m
[37m[2024-05-28T07:10:36.678468Z] [debug] [pid:63630] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:20203/qB7uxifSCr757qLM/broadcast[0m
[37m[2024-05-28T07:10:37.354643Z] [debug] [pid:63630] commands process exited: 0[0m
[37m[2024-05-28T07:10:37.454900Z] [debug] [pid:63630] done with command server[0m
[37m[2024-05-28T07:10:37.454976Z] [debug] [pid:63630] isotovideo done[0m
[37m[2024-05-28T07:10:37.455425Z] [debug] [pid:63842] EVENT {"data":{"path":"\/machine\/peripheral-anon\/device[3]\/virtio-backend"},"event":"NIC_RX_FILTER_CHANGED","timestamp":{"microseconds":472231,"seconds":1716879868}}[0m
[37m[2024-05-28T07:10:37.455550Z] [debug] [pid:63842] EVENT {"data":{"guest":true,"reason":"guest-reset"},"event":"RESET","timestamp":{"microseconds":24622,"seconds":1716880052}}[0m
[37m[2024-05-28T07:10:37.455639Z] [debug] [pid:63842] EVENT {"data":{"guest":true,"reason":"guest-reset"},"event":"RESET","timestamp":{"microseconds":32570,"seconds":1716880052}}[0m
[37m[2024-05-28T07:10:37.455746Z] [debug] [pid:63842] QEMU status is not 'shutdown', it is 'running'[0m
[37m[2024-05-28T07:10:37.455873Z] [debug] [pid:63630] backend shutdown state: [0m
[33m[2024-05-28T07:10:37.456219Z] [info] [pid:63842] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json[0m
[37m[2024-05-28T07:10:38.514020Z] [debug] [pid:63842] Passing remaining frames to the video encoder[0m
frame= 1009 fps=1.8 q=0.0 Lsize=     898kB time=00:00:42.00 bitrate= 175.1kbits/s speed=0.0729x    
video:890kB audio:0kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: 0.819116%
[37m[2024-05-28T07:10:39.084104Z] [debug] [pid:63842] Waiting for video encoder to finalize the video[0m
[37m[2024-05-28T07:10:39.084183Z] [debug] [pid:63842] The external video encoder (pid 64033) terminated[0m
[37m[2024-05-28T07:10:39.084241Z] [debug] [pid:63842] The built-in video encoder (pid 64034) terminated[0m
[37m[2024-05-28T07:10:39.084766Z] [debug] [pid:63842] QEMU: qemu-system-x86_64: terminating on signal 15 from pid 63842 (/usr/bin/isotovideo: backen)[0m
[37m[2024-05-28T07:10:39.085322Z] [debug] [pid:63842] sending magic and exit[0m
[37m[2024-05-28T07:10:39.085551Z] [debug] [pid:63630] received magic close[0m
[37m[2024-05-28T07:10:39.117678Z] [debug] [pid:63630] backend process exited: 0[0m
Use of uninitialized value $name in pattern match (m//) at /usr/lib/os-autoinst/OpenQA/Isotovideo/Utils.pm line 332.
	OpenQA::Isotovideo::Utils::handle_generated_assets(OpenQA::Isotovideo::CommandHandler=HASH(0x5597fecf45c0), "") called at /usr/bin/isotovideo line 204
	eval {...} called at /usr/bin/isotovideo line 161
[37m[2024-05-28T07:10:39.218917Z] [debug] [pid:63630] stopping backend process 63842[0m
[37m[2024-05-28T07:10:39.218988Z] [debug] [pid:63630] done with backend process[0m
63630: EXIT 0
[2024-05-28T07:10:39.267688Z] [info] Isotovideo exit status: 0
[2024-05-28T07:10:39.296719Z] [info] +++ worker notes +++
[2024-05-28T07:10:39.296837Z] [info] End time: 2024-05-28 07:10:39
[2024-05-28T07:10:39.296893Z] [info] Result: done
[2024-05-28T07:10:39.300488Z] [info] Uploading autoyast_btrfs_quota.xml
[2024-05-28T07:10:39.361254Z] [info] Uploading clone-autoinst.xml
[2024-05-28T07:10:39.402585Z] [info] Uploading clone-installedSystem.xml
[2024-05-28T07:10:39.447955Z] [info] Uploading clone-y2logs_clone.tar.bz2
[2024-05-28T07:10:39.539488Z] [info] Uploading repos-y2logs.tar.bz2
[2024-05-28T07:10:39.597563Z] [info] Uploading video.webm
[2024-05-28T07:10:39.650189Z] [info] Uploading autoinst-log.txt
